Migrations - RangeError: Maximum call stack size exceeded

[jamesdixon]

I'm running into a very strange error when running Knex migrations.

For context, I'm speaking specifically about running migrations during testing. Before each test, my database is completely wiped and migrations are run. I use the following script:

Bookshelf.knex.raw('DROP OWNED BY scout CASCADE')
            .then(() => Bookshelf.knex.migrate.latest())
            .then(() => Bookshelf.knex.seed.run())

This has been working perfectly for months. Yesterday, I added a new field to one of my tables and suddenly I started receiving the following error:

Knex:warning - migrations failed with error: Maximum call stack size exceeded
Unhandled rejection RangeError: Maximum call stack size exceeded
    at TableBuilder.(anonymous function) [as timestamps] (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/knex/lib/schema/tablebuilder.js:140:32)
.
.
[repeats literally 1000 times]
    at TableBuilder.(anonymous function) [as timestamps] (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/knex/lib/schema/tablebuilder.js:140:32)
.
.
at TableBuilder.knex.schema.createTable [as _fn] (/Users/jamesdixon/Projects/scout/platform/app/api/db/migrations/20150807152917_surcharge.js:33:11)
    at TableBuilder.toSQL (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/knex/lib/schema/tablebuilder.js:71:12)
    at SchemaCompiler_PG.createTable (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/knex/lib/schema/compiler.js:62:23)
    at SchemaCompiler_PG.toSQL (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/knex/lib/schema/compiler.js:51:26)
    at SchemaBuilder.toSQL (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/knex/lib/schema/builder.js:57:43)
    at /Users/jamesdixon/Projects/scout/platform/app/api/node_modules/knex/lib/runner.js:52:32
    at tryCatcher (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/util.js:16:23)
    at /Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/using.js:185:26
    at bound (domain.js:280:14)
    at runBound (domain.js:293:12)
    at tryCatcher (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/promise.js:510:31)
    at Promise._settlePromise (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/promise.js:567:18)
    at Promise._settlePromise0 (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/promise.js:612:10)
    at Promise._settlePromises (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/promise.js:691:18)
    at Promise._fulfill (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/promise.js:636:18)
    at PromiseArray._resolve (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/promise_array.js:125:19)
    at PromiseArray._promiseFulfilled (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/promise_array.js:143:14)
    at Promise._settlePromise (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/promise.js:572:26)
    at Promise._settlePromise0 (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/promise.js:612:10)
    at Promise._settlePromises (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/promise.js:691:18)
    at Async._drainQueue (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/async.js:138:16)
    at Async._drainQueues (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/async.js:148:10)
    at Immediate.Async.drainQueues (/Users/jamesdixon/Projects/scout/platform/app/api/node_modules/bluebird/js/release/async.js:17:14)
    at runCallback (timers.js:574:20)
    at tryOnImmediate (timers.js:554:5)
    at processImmediate [as _immediateCallback] (timers.js:533:5)

You'll notice that right after the repeating piece ends, the stack trace points to one of my migrations. Here's the thing, the name of that file changes on every run and whenever I look at those files, there's nothing wrong.

Here's a strange thing: when running my tests, this doesn't seem to occur right away. A few tests are run before failure. When I take a look at the migrations table after the failure, the number of records is never consistent, so it doesn't seem that a specific migration is causing the issue.

Here's the really strange thing: if I remove a single field from ANY one of my 42 migrations, everything works completely fine. If I add a field back to any one of those migrations, regardless of name or type, I see the error again.

It's almost like I've hit some sort of field limit or there is some sort of leak. I'm running v0.12.2, but have tried versions of 0.11.x and 0.10.0 and see the same issue.

I'd post my files if I could, but there's just too many.

Appreciate any help -- this is a doozy.

Thanks!

[tgriesser]

I was actually just informed by someone else of a similar looking issue and I have been scratching my head as to what might be causing it... Can you confirm the version of node you're seeing the issue in?

[jamesdixon]

Thanks for the quick reply!

I'm seeing the issue on Node 6.7. More than happy to test on other versions if you'd like.

[tgriesser]

Yeah, since that's the latest would you mind checking if it shows up on the last few versions prior? Thanks!

[jamesdixon]

I should have tested on another version before; my apologies.

That said, I did some testing and can confirm it starts acting up in Node 6.5 and is present in 6.6 and 6.7. Node 6.4 and below seem to work fine.

[fl0w]

Hm, we actually encountered these errors as well, it was in one of our tests where we had to migrate back and forth. I'll try to find a commit/issue and supply potentially resourceful information if possible.

[ErisDS]

Not sure if this is what Tim was referring to, but we had a similar bug on node v6 only in our custom migration system with regard to the isNullable() function. This PR: TryGhost/Ghost#7511 seemed to fix the error.

It would take 6/7 goes through travis to get the our tests to pass. Meaning the problem is also intermittent. Very, very, very odd.

[tgriesser]

@ErisDS do you know which version of node?

[tgriesser]

I'm guessing this is an example failure case, where it seems it's failing in node 6.7 - https://travis-ci.org/TryGhost/Ghost/jobs/164642712

The fact that this has just started happening recently makes me think it's potentially an issue related to the v8 bump in node >= 6.5

[ErisDS]

Yeah that is one example, we see this fail in different ways. Another example is this (copied and pasted before a restart):

https://gist.github.com/ErisDS/a63a989d7c46dfa487a3f8819729bb66

It was all within the last few days, so v6.7

I am collecting failures in gists and posting them here: TryGhost/Ghost#7470, only the last few show the proper error messages, because we refactored our error handling and now the errors bubble up properly 😁

[fl0w]

@ErisDS Sounds like what we experienced, but as db latency got higher the problem occurred more predictably.

[fl0w]

@tgriesser I'll try to find time to test this (if I can reproduce this predictably) on node v7 (v8 5.5).

[tgriesser]

I split out the offending code paths so this hopefully shouldn't happen. Also opened a ticket on nodejs about it (and mentioned all of you) if you'd be able to provide any other info that might be helpful. If it is a v8 regression its a bit concerning even if we patched it here.

@jamesdixon Any chance you could npm install from master and see if things are fixed?

[jamesdixon]

@tgriesser I can confirm this appears to be resolved in 0.12.5.

Thanks a ton for looking into this and providing a fix!