TL;DR: what was the bug? (spoilers!): https://gist.github.com/trptcolin/6039cd454acfe6e820d13cbdce5e4064
- Minor text change for the company blog; let’s get it done!
JEKYLL_ENV=production bundle exec jekyll upload -e staging
Liquid Exception: ExecJS::ProgramError in /_layouts/default.html
- execjs, hmm, do i have node installed?
node --version
- yes, v11.14.0
bundle open jekyll-s3-upload
to read code & see this command is doing- looks like it builds before uploading (
Jekyll::Commands::Build.build(site, jekyll_config)
) - https://github.com/8thlight/jekyll-s3-upload/blob/60dd52f937db21d1265cb9a7fdcdf438730e32d2/lib/jekyll/commands/s3_upload.rb#L51
- looks like it builds before uploading (
bundle exec jekyll build
- works already when run alone - but it fails in our context. what’s different?
- add
require “pry”; binding.pry
to jekyll-s3-upload gem on filesystem - want to see what surprises are in store- "Sorry, you can't use Pry without Readline or a compatible library. Possible solutions: Rebuild Ruby with Readline support […]"
- ugh, this has happened a bunch of times, i think maybe something ended up upgrading readline in homebrew
- ok, going to reinstall ruby and hope it picks up the readline that’s in homebrew
ruby -version
-> 2.3.8rbenv uninstall 2.3.8
;rbenv install
(.ruby-version
already dictates 2.3.8)bundle install
(crossing fingers for no native-extensions whammies)- welp, nokogiri install failed,
The file "/usr/include/iconv.h" is missing in your build environment [...]
- luckily this is covered in our README - link to https://nokogiri.org/tutorials/installing_nokogiri.html#unable-to-find-libraries-on-macos-mojave - essentially
/usr/include
is expected to have headers, but it doesn’t under Mojave - need to run
open /Library/Developer/CommandLineTools/Packages/macOS_SDK_headers_for_macOS_10.14.pkg
- welp, nokogiri install failed,
bundle install
again - worked!- ok where were we?… right, adding pry.
bundle exec pry
- works- hrm, maybe the headers caused the execjs issue in the first place? let’s bounce all the way back to the top level
JEKYLL_ENV=production bundle exec jekyll upload -e staging
again?- nope, same failure. back to the process, wanting to see surprises / differences between
jekyll build
and whatever’s running through this gem
- nope, same failure. back to the process, wanting to see surprises / differences between
- re-add
require “pry”; binding.pry
, right before the#build
command gets run- config all looks fine, let’s run the command within
pry
- config all looks fine, let’s run the command within
Jekyll::Commands::Build.build(site, jekyll_config)
- yep, fails the same way. now let’s get ourselves a backtrace
begin; Jekyll::Commands::Build.build(site, jekyll_config); rescue => e; e; end
- actually my first try was assigning a different variable, because i forgot about
e
not being lexically scoped here - but it’s still available outside thisbegin
/end
context - cool.
- actually my first try was assigning a different variable, because i forgot about
e.backtrace
- i see some stack frames around liquid rendering (already implied by the original error message),
jekyll-assets
,sprockets
, anduglifier
before finally hittingexecjs
and the error - maybe we can pry into this last frame, the
execjs
thing… it’s this line (line # given in the backtrace): https://github.com/rails/execjs/blob/4f2fc87a55ea4f3195363ae3620d9d5cae47e9fc/lib/execjs/external_runtime.rb#L39
- i see some stack frames around liquid rendering (already implied by the original error message),
- add
require “pry”; binding.pry
before that line in the installed gem on the filesystem (extract_result(@runtime.exec_runtime(filepath), filepath)
)- need to make notes on what gems i’m changing so i can
gem pristine
them once this is solved
- need to make notes on what gems i’m changing so i can
- inspect
@runtime
and@runtime.methods.sort - "”.methods
to start understanding this a bit- accidentally hit some nested
pry
sessions since we’re already in a “runtime” instance, bailed
- accidentally hit some nested
- run just the innermost piece,
@runtime.exec_runtime(filepath)
- empty string… hrm, so
extract_result
must not want to handle an empty string… - seems like either the
exec_runtime
value is wrong, or””
should be handled better, not sure which...
- empty string… hrm, so
- look at the file in
filepath
- a tempfile w/ a bunch of js in it… looks like a lot of library code
- feeling a little stuck right now… wondering why this code doesn’t fail in the top-level CLI
jekyll build
… let’s leave thepry
in place and run that, see if it gets hit.
bundle exec jekyll build
…- still works, and never hits
execjs
- why not?
- still works, and never hits
- look at
jekyll-assets
on github- aha - some examples imply behavior change based on
JEKYLL_ENV=production
or not - so maybe if we
jekyll build
w/ that env var set...
- aha - some examples imply behavior change based on
JEKYLL_ENV=production bundle exec jekyll build
- yes, ok, now this fails in exactly the same way as the upload, so we can rule out config difference between those two things and in fact rule out
jekyll-s3-upload
entirely as the culprit. - what if we just binary search the
_layouts/default.html
template file? in fact...
- yes, ok, now this fails in exactly the same way as the upload, so we can rule out config difference between those two things and in fact rule out
- delete all of
_layouts/default.html
except<html></html>
- still fails for the same reason, but now it’s on a different template! (a specific blog post)
- what’s similar between that template and the top-level layout?
- that post has a
{% javascript path/to/thing %}
, and so did the layout - deleted just those liquid tags from the whole site; whole build passes
- meanwhile - this has been going on far too long - let’s have someone else deploy the blog, make sure it’s just my machine w/ the issue.
- yes, that’s the case - Kyle’s setup builds & deploys just fine
- is the lesson here “rip all the javascript out of the blog”? seems appealing at this point, but no.
- time for a coffee break... stay tuned for the thrilling conclusion...
- let’s take a closer look at which javascript is being compiled… moving the
require “pry”; binding.pry
up to the top of the#exec
function (https://github.com/rails/execjs/blob/4f2fc87a55ea4f3195363ae3620d9d5cae47e9fc/lib/execjs/external_runtime.rb#L26)- incoming
source
is literally””
- wacky. but it looks like this might come from the end of#initialize
- and@source
has been set to some context - and the output of the
@runtime.exec_runtime
call is""
- incoming
- add pry stuff one level up the stack, before https://github.com/lautis/uglifier/blob/v2.7.1/lib/uglifier.rb#L171
- eval’ing generic javascript code like
ExecJS.eval "'red yellow blue'.split(' ‘)”
works totally fine - maybe the uglify.js source code has an issue?
- eval’ing generic javascript code like
ExecJS.compile uglifyjs_source
- fails in the usual way - what is
uglifyjs_source
? looks like https://github.com/lautis/uglifier/blob/v2.7.1/lib/uglifier.rb#L193-L197 - this should really be the “uglify.js” that ships w/ the gem i’d assume...
- fails in the usual way - what is
ExecJS.compile IO.read("/Users/colin/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/uglifier-2.7.1/lib/uglify.js")
- this seems to work!!!
- oh, looking back at the uglifyjs_source code - it’s concatenating 3 js files
prefix="/Users/colin/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/uglifier-2.7.1/lib/"; sources = ["es5.js", "split.js", "uglify.js"].map{|f| IO.read(File.join(prefix, f))}.join("\n"); ExecJS.compile sources
- fails again- so it’s not an encoding thing
- remove one filename at a time from
sources
es5.js
is the only one that fails, hrm...
ExecJS.compile(IO.read("/Users/colin/.rbenv/versions/2.3.8/lib/ruby/gems/2.3.0/gems/uglifier-2.7.1/lib/es5.js"))
- seems to be a minimal failing case
- ask kyle what
node --version
he’s got - am i hitting a case where a new node has broken this setup?- he’s on v9.8.0 - and i’m on v11.14.0. could be a difference there
- clone uglifier (https://github.com/lautis/uglifier) and see if the master branch version of es5.js compiles:
ExecJS.compile(IO.read("/Users/colin/Projects/oss/uglifier/lib/es5.js"))
- it does compile!
- let’s look at the history of this file. we could theoretically bisect to find a working uglifier version
- wait no, our uglifier dependency in the blog is at the top level. instead let’s just try updating uglifier to the latest version… really really hoping the transitive dependencies don’t cause too much pain
- update uglifier to version 4.1.20 in
Gemfile
andbundle update uglifier
- this is unheard-of, this worked with no pain or dependency conflicts…
- the build is running for longer than usual, oh goodness…
- it WORKED!!
- OK now i want to make sure this update doesn’t also break Kyle / older NodeJS versions - having him try this same update.
- we’re good! can’t believe it.
- let’s go ahead and push a PR up to the blog repo for the update, but while the build is running, i want to understand exactly what caused this.
- and, also still need to
gem pristine
everything i touched (uglifier, jekyll-s3-upload, execjs)
- revert to the dependency on the older version of uglifier to get our pry activated again
git tag -l
in the uglifier source code checkout to see what other versions we can try- run the top-level
jekyll build
command again to get back into ourpry
(in the gem dependency version of uglifier, 2.8.0) right before theExecJS.compile
ExecJS.compile(IO.read("/Users/colin/Projects/oss/uglifier/lib/es5.js”))
here - theProjects/oss
uglifier location is just being used to vary the contents of es5.js- results:
- works on master (the recent passing case)
- works on v4.0.0
- fails on v2.7.1 (our original failing case)
- works on v3.1.0
- works on v3.0.0
- works on 2.7.2
- so! this works due to some change that came in between 2.7.1 and 2.7.2
git log --stat v2.7.1..v2.7.2 lib/es5.js
- one commit!
git show 614f120f2ba620e5b2faa87bb6351b093beb2f09 lib/es5.js
- OMG this 1-line change. wow.
- previous:
return "property" in object;
- new:
return true;
- what the heck am I looking at here, what is
return “property” in object;
??! - ah, ok,
“property” in object
is a predicate (is this string”property”
a property on the object - can i run an old version of node and see if lower-cased
object
was a global thing at some point? what’s this syntax?
ls -l $(which node)
->/usr/local/bin/node -> ../Cellar/node/11.14.0_1/bin/node
- no peer directories for other node versions, need to install an old one. how do i do that?
- google around for
downgrade node
, remember that i haveasdf
plugins installed for a few other languages;asdf plugin-add nodejs
asdf install nodejs 9.8.0
- fails due to some GPG key tomfoolery; i’m not going down this rabbit hole. let’s find someone else in the office who has an old node version
- Kevin had one - we tried a few things and i thought i saw the issue
- the lower-cased
object
is an undefined value in both Node versions, and i thought the thrown error looked different, but back at my spot i realize my experiment was flawed: i typed something different than Kevin did. - i’m realizing i want to try a lot more things on that other node version, but Kevin has his own stuff going on and i don’t want to have to keep asking him to run every little tiny experiment. need extremely fast experiment cycles -> need an older node installed myself and able to switch
- ah found
brew install node@8
(w/ a bit of googling); let’s do thatexport PATH="/usr/local/opt/node@8/bin:$PATH”
JEKYLL_ENV=production bundle exec jekyll build
- verified that uglifier 2.7.1 (which failed w/ recent node) does work w/ node@8
- ran the code that changed under both [email protected] and [email protected]
- everything appears to work the same: https://github.com/lautis/uglifier/blob/v2.7.1/lib/es5.js#L307-L320
- meeting time...
- ok, where were we - right, figuring out exactly what’s different between the node versions
- hrm, output is the same, but let’s comment lines out 1 by 1 and see when things break down….
- making changes to the source checkout of uglifier, in
es5.js
- running with node v11.14.0, where we saw the breakage before, with the pry breakpoint in the uglifier gem dependency since that’s where things break - really only need to get into pry once, and then:
- can run that explicit
ExecJS.compile(IO.read("/Users/colin/Projects/oss/uglifier/lib/es5.js”))
for every change toes5.js
- we know what line is in question, but it’s totally non-obvious what’s going wrong.
- 1 line at a time commenting doesn’t yield any insights - let’s change the impl
- add
console.log(“ohai”)
to the body of the fn defined byObject.defineProperty = function defineProperty(object) { }
- this fails at runtime - “Cannot read property ‘log’ of undefined"
- so there’s something calling this method!
- how can we log, then? googling...
- let’s try
process.stdout.write
instead...net.Socket is not a constructor
- let’s google that...- programming is glamorous huh?
- no real luck googling; maybe zoom out.
- who’s calling this? stack trace shows this being called as part of
Function.defineProperty
… wonder what happens in Node 8?
- export a new PATH to find node 8 first and run the same code.
- i should just have 2 terminal sessions, one running 8 and one running 11, so i don’t have to bounce my pry session when experimenting (short cycles rule when debugging!)
- ooh, for Node 8 this still works… why?
- what if i change the code to just
throw “ohai”
instead ofprocess.stdout.write
? - AHA - something about Node 8 does not end up calling our new defineProperty function
- double check that the function is still being defined, by moving the
throw
to before the fn definition- sure enough… move the throw back.
- try changing
Object.defineProperty =
toFunction.defineProperty =
, and same deal.
- OK, so we’ve now learned that Node 11.14.0 calls
Function.defineProperty
(which calls our definedObject.definedProperty
, and we have a stack trace showing some filenames involved (util.js, internal/streams/legacy.js, internal/boostrap/loaders.js, stream.js, net.js)- do we dare figure out where that code lives? maybe in uglify.js or even in node.js itself?
- oh yes, we dare. google for the longest one "internal/bootstrap/loaders.js” - looks like it’s in Node itself, here we go...
- search nodejs repo (https://github.com/nodejs/node) for
defineProperty bootstrap
- found some Issues hits, in particular nodejs/node#25816 which has a comment "can you add a test demonstrating that modifying Object.defineProperty or something doesn't break internal code?"
- this sounds ominous. links to another issue:
- nodejs/node#18795 “should internal modules be affected by monkey-patching” - some spirited discussion here around exposing internals to users for monkey-patching. this is exactly what uglifier is doing with
Object.defineProperty
- OK, I’m starting to feel confident that this is the issue, and considering chiming into this last Node issue to say so.
- But:
- I don’t know, maybe Node folks will consider the monkey-patching to be the bug? it’s userspace so feels like it should be resilient to this, as mscdex says on the issue.
- Even so, I’d like to have a minimal repro case that doesn’t involve all these Ruby libraries if I want to present it to the Node folks.
- found some Issues hits, in particular nodejs/node#25816 which has a comment "can you add a test demonstrating that modifying Object.defineProperty or something doesn't break internal code?"
- trying to minimize to just Node...
- running
node /Users/colin/Projects/oss/uglifier/lib/es5.js
runs without errors in both cases. - add
console.log
to the bottom, doesn’t print in node 11… this is promising
- running
- single file with
Object.defineProperty = function defineProperty(object) { return object; }; console.log("hi”);
- save as/tmp/sample.js
- prints in node 8; doesn’t print in node 11
- https://gist.github.com/trptcolin/7f9eb75a11c4c165ff62678ef7140a69
- back on the github issue & related PR, looks like the relevant changes went in in Node 11.10. it’d be nice to validate that there’s a behavior difference across that gap.
mkdir ~/Practice/node-playground
npm install [email protected]
&&npm install [email protected]
./node_modules/node/bin/node /tmp/sample.js
- works fine- oh, these versions clobber each other; need to try 11.9.0 again - works fine too
- 11.11.0? fine
- 11.12.0 - broken
- so let’s see the changelog for 11.12.0: https://github.com/nodejs/node/blob/master/doc/changelogs/CHANGELOG_V11.md#11.12.0
- lots of stuff; hrm.. want to clone & see the commits so i can cross-reference w/ files named in the stack trace i got
git clone [email protected]:nodejs/node.git
- it’s getting serious now
- but the train ride's over, time to get in the car and get home to the kiddos.
- ok first let’s have 2 node-playground directories to re-check that the difference is definitely this 11.11.0 -> 11.12.0 transition.
- I don’t want to be spelunking through node commits only to find i was lookingin the wrong place
cd ..; mv node-playground node-11.12.0-playground; mkdir node-11.11.0-playground; cd node-11.11.0-playground ; npm install node@
- validate that
./node_modules/node/bin/node --version
is the expected value in both directories - and
./node_modules/node/bin/node /tmp/sample.js
to re-validate the behavior difference - yep, this is the transition point
- validate that
- in the node checkout,
git tag -l
- looks likev11.11.0
git log v11.11.0..v11.12.0 --stat
- lots of stuff; whew…
git log v11.11.0..v11.12.0 --oneline | wc -l
-> 156 commits - what about just changes to
lib
? not sure that’s where the issue lives, but it’s where the node code i’ve browsed so far via those GH issues lives.
- lots of stuff; whew…
git log v11.11.0..v11.12.0 --oneline lib | wc -l
-> 35 commits, still a lot but feels more tractablegit log v11.11.0..v11.12.0 -p lib
and searching fordefineProperty
- lots of hits, hrm- looking back at the stack trace, not wild about the way it only logs after the
Object.defineProperty
call - would like to see incremental output in the failing case
- added
console.log
to top & bottom of/tmp/sample.js
- and now both node versions work!!!- ok, now this is seeming even more edge-case-y
- https://gist.github.com/trptcolin/ad3b18cf251f5316a0ea5dc306efcf70
- is it just console.log? can’t be, right? wait, how did this start? ExecJS compile was failing specifically on that one es5.js file, but that was because it had the
Object.defineProperty
monkeypatch in it.
- change
console.log
toprocess.stdout.write
- got a stack trace this time (for v11.12.0; different from the one earlier when weconsole.log
’ed within thedefineProperty
definition- re-adding logging within that
defineProperty
makes both versions trace the same! - searched through the git logs some more for defineProperty - didn’t find anything obvious, but this
--frozen-intrinsics
commit adds a lot of code, let’s play w/ that
- re-adding logging within that
./node_modules/node/bin/node --frozen-intrinsics /tmp/log_end.js
- fixes the issue under node v11.12.0 (!) - also emits the “is experimental” warning, but this does let the
console.log
work when it’s only at the end of this file - ok, so maybe there’s explanation in the PR where this came in...
- nodejs/node#25685 - lots of stuff, kind of beyond my understanding of node, but it also links to some other resources that seem interesting:
- a security model doc: https://docs.google.com/document/d/1h__FmXsEWRuNrzAV_l3Iw9i_z8fCXSokGfBiW8-nDNg/edit?ts=5c1adaed#heading=h.q1x6on1y6aju
- an ECMAScript spec discussion: tc39/ecma262#1320
- nodejs/node#25685 - lots of stuff, kind of beyond my understanding of node, but it also links to some other resources that seem interesting:
- oh, maybe this just prevents Object.defineProperty from being overwritten successfully in the first place… what if i put garbage in that function to test that theory like
throw “hi”
?- yeah, sure enough, it just prevents the monkeypatch from even happening. so this likely isn’t the breaker
- kind of demoralized… [checks social media for awhile]
- should i try building node versions and bisecting? maybe a
git bisect
script?- let’s try building a single node version first; see how it is.
- fixes the issue under node v11.12.0 (!) - also emits the “is experimental” warning, but this does let the
- going through https://github.com/nodejs/node/blob/master/BUILDING.md
- looks like they require python 2; i’ve got 3 and it’s noted as experimental.
- also have 2 but it’s
python2
- could set up symlinks if this doesn’t fly
configure; make -j4
- noting start time: 6:38am
- hopefully this first one will take the longest and
make
will be able to detect it doesn’t need to re-compile most of the files that haven’t changed... - 20m later DONE
- last lines of output reference
out/Release/node
-out/Release/node --version
-> v11.12.0 - and
out/Release/node /tmp/log_end.js
has the expected (bad) result
git bisect bad
- to mark this version bad (git helpfully offers togit bisect start
for me, thanks git!- now need to checkout the known good version at v11.11.0 and re-build (./configure && make -j4) - start time 7:01am, see you in up to 20m...
- ...
- took ~16m that time
- yep,
out/Release/node /tmp/log_end.js
works, so:
git bisect good
- and git jumps to the next commit for me, yay!- build time! starting at: 7:18am
- while this is building: yes i’m banging on this on a Saturday. but in my defense, this is the first time coding on a Saturday in awhile, and i do like figuring out these gnarlier issues. family is still mostly in bed, but i won’t have much time left here.
- whoa, done within 5min, yay!
out/Release/node /tmp/log_end.js
prints “end” - so,git bisect good
and on to the next one, build starting at 7:25- git bisect good -> new build starting 7:27. feeling pretty happy with the node build right now - this could have been a whole other level of nonsense, but it wasn’t.
- need to record the commits here - i think the previous one i marked good was 5ad9929, and now we’re building 6adcc6f
- building 6adcc6f... git bisect good
- building 9e82ee9… git bisect bad (i.e. no output) - aha! we’re nearly there, i think! "4 revisions left, roughly 2 steps"
- building 3e54f90… git bisect good
- building 6f68570… luckily these builds are going much faster (yay make!)…. git bisect bad
- buidling c14aa07… git bisect bad
- ID’ed c14aa07b94d684de8e2a23a54d0e6a3c25a2e460 as the commit where things start failing for me
- now, could this be an issue that’s already been fixed? let’s build master. i assume this will be pretty slow, so while it builds let’s look at that commit & relevant PR more closely:
- Reviewing https://github.com/nodejs/node/commit/c14aa07b94d684de8e2a23a54d0e6a3c25a2e460 - looks like it adds an
Object.defineProperty
- but I don’t see any aliasing to those “primordials” i saw yesterday in a nodejs commit within this file as of this commit (https://github.com/nodejs/node/blob/c14aa07b94d684de8e2a23a54d0e6a3c25a2e460/lib/net.js)- but this also isn’t the first
Object.defineProperty
call in this file - are the others some different potential breakage? or working coincidentally? - while master is building, searching issues for “primordials”, found some potentially relevant stuff, but not directly useful things
- what about looking at
net.js
on master? sure enough: https://github.com/nodejs/node/blob/030fa2ea440789990b363a6bcd7dec75ee3e8fc6/lib/net.js#L24 (I hit “y” on github to make sure my links still go to the right line, even whenmaster
points to a different SHA) - so i have a suspicion that master will just work™ once it finally finishes building - 🤞that i’m starting to understand correctly, but if this is already fixed, it might feel anticlimactic… which i’m actually fine with at this point, it’s been an interesting dive
- but this also isn’t the first
- still building, ok, let’s see when that line
const { Object } = primordials;
came intonet.js
- using https://github.com/nodejs/node/blame/master/lib/net.js- aha! master works! shall we bisect again to find the fix?
git bisect reset; git checkout master; git bisect good; git checkout v11.12.0; git bisect bad
- building 5d8373a… [longer hops between commits means more stuff changes, means longer builds] - git bisect good
- building 1e09629… git bisect good
- building 618f641… [starting to get anxious that maybe
git bisect
really needs to find a bug and not a fix — in which case this current bisect process will fail… gonna read some docs]
git help bisect
- ah crud, yep, i want to find the fix, so i need to dogit bisect start --term-new fixed --term-old broken
and mark things broken & fixed 😞- bailing on the bisect process, but hopefully i can limit the search space to start since i took notes on passing/failing SHAs...
- ugh, there are some gnarly merges going on, maybe backporting branches & stuff? all these commits have the same # of changes from them to master (3173 - via e.g.
git log master..618f641 --oneline | wc -l
) so those SHAs don’t really help me. - let’s take that commit that brought in
const { Object } = primordials;
and guess that maybe it is what fixes the bug. it’s got comments on its related PR (nodejs/node#27146) about version 12.0.0, so let’s start there. - birthday party time for kindergartner’s classmate!
- ...
- alright, v12.0.0 works fine -
git bisect fixed
- related to the above “what’s w/ the merges” question, i see the message "Bisecting: a merge base must be tested” - stackoverflow’ing for that while i’m building the thing https://stackoverflow.com/questions/45107500/git-bisect-says-bisecting-a-merge-base-must-be-tested
- building 5d8373a - dang i’ve already tested this, ctrl-c and
git bisect fixed
- git bisect gives up maybe? "This means the first 'broken' commit is between 5d8373a498a50b1387464391402ef22636439303 and [a4ff9dfaf1d135e0ad0f358c74f4a29c44d5681d]."
- classic, there are 2209 commits in that range:
git log 5d8373a498a50b1387464391402ef22636439303..a4ff9dfaf1d135e0ad0f358c74f4a29c44d5681d --oneline | wc -l
. can we bisect on that range i guess? - this is lame, i don’t care about the first “broken” commit - i want the first “fixed” one...
- alright, v12.0.0 works fine -
- let’s try correlating via commit messages…
git log v11.12.0 -1 —oneline
is SHA a4ff9dfaf1git log v12.0.0
and search for “11.12.0” - same release is 969c63a0f1deffaaffcf2bec841bd4a7831559c3 in the v12.0.0 tree… maybe we can try that linegit bisect reset; git bisect start --term-new fixed --term-old broken
git checkout 969c63a0f1deffaaffcf2bec841bd4a7831559c3 && git bisect broken
(assuming here, possibly wrongly, that this commit has the same issue - saving time, but it’s a bet)git checkout v12.0.0 && git bisect fixed
- building 83c35dc… [wonder if i think about writing up a summary or just leave the journey here as-is, leaning towards as-is. also it’d be nice to pass a script to
git bisect
. i’m intimidated by that in general, but this case should actually be fairly easy since “no output” == broken and “output == ‘end'” == fixed. but i’m not gonna bother, just gonna check back into the home office from time to time to check on script runs - don’t wanna burn more time.]git log 83c35dc..v12.0.0 --oneline | wc -l
is only 271, and because binary search is log2 n, there are only 8-9 more of these, and i expect they’ll all get faster as before- no output ->
git bisect broken
- building d141330 [looks like
deps
is where openssl, v8, uv live - and those are the changes that i assume are taking forever to compile. not super relevant, butgit log
’ed through the changes there while i’m waiting and i see we’re not done yet…]- yeah, writing up a recap as a separate file here.
- ...
- d141330 -
git bisect broken
- building 2400cbc - looking at commits, i expect this to be broken, because:
git log d141330..2400cbc --oneline --stat lib
has the commit "908292cf1f lib: enforce the use of Object from primordials” that i’ve been expecting to be the fix- i’m wrong! it’s fixed here. dang. is this going to get crazier instead of clearer?
- oh, that’s because my expectation wasn’t thought-through enough. i want 2400cbc to be the end of the search space, and “fixed” is the end state. so the working theory may still be the case.
- building 25df3c1 -
git bisect fixed
- building 5b9e570 - this is before the commit i suspect of fixing, so this should be broken this time if it’s right.
- wait a minute. why didn’t i just jump right to the commit before the fix and the fix commit, if i’m so smart? 🤦 ok anyway, that could possibly waste time if my guess is wrong, so i’m ok continuing down the definitely-useful-and-correct binary search
- sure enough, it’s
git bisect broken
, cool. 3 steps left, excitiiiiing!
- building 06c10cd - expecting broken based on where it sits in
git log 5b9e570..25df3c1 --oneline
git bisect broken
- building 56354d4 - [getting closer!] -
git bisect broken
- building 908292cf1f [this is the commit i am “accusing” of fixing the bug] -
git bisect fixed
- building 9ad5106 -
git bisect broken
- d141330 -
- thrilling conclusion: sure enough, the bug is fixed by 908292cf1f551c614a733d858528ffb13fb3a524: https://github.com/nodejs/node/commit/908292cf1f551c614a733d858528ffb13fb3a524
- very, very nice touch here that it’s added to an eslint config and so won’t resurface.
- i’m gonna pop onto that issue and say thanks for fixing it 🙂
- and also look for a node 12 release on homebrew 🙂 - it exists! installing 12.1.0 now.
this is pretty wonderful. we could all learn a lot more if this type of debugging process was shared bt. developers. pairing is one way to do this.