TypeError: object is not a function

[anodynos]

Starting with 3.6.0, but possibly even before that, there is a TypeError: object is not a function error thrown at seemingly random situations, as also discussed in #345.

The following coffee code manages to reproduce it: it fails with when@3.6.0 running on node v0.10.33/coffeescript 1.8, on both Ubuntu 14x64 & Windows 7x64 after exactly 393 overall iterations :-/

The error is very strangely random-y: although this code fails predictably (at overall iteration noted as registering catch # 393), almost any change affects the error and might not even throw at all or throw longer after - even a console.log change, or the useless loops and promises formation etc might affect the outcome...

I highly sympathize whoever is going to debug this unpredictable ghost busting monster ;-(

fs = require 'fs'

When = require 'when'
When.node = require 'when/node'
When.sequence = require 'when/sequence'
readFileP = When.node.lift fs.readFile

path = require 'path'
expand = require 'glob-expand'
esprima = require 'esprima'

jspath = '../node_modules/lodash'

arrayItems = []
for i in [1..1000]
  arrayItems.push do (i)-> -> When(i)

fileTxt = null

files = expand {cwd: jspath, filter: 'isFile'}, ['**/*.js']
for file in files
  fileTxt = fs.readFileSync(path.join(jspath, file), 'utf8')
  esprima.parse(fileTxt)
  console.log "test parsing file is ok `#{file}`"

catchCount = 0
When.iterate(
  (i)-> i + 1
  (i)-> !(i < arrayItems.length)
  (i)->
    item = arrayItems[i]

    When.iterate(
      (j)-> j + 1
      (j)-> !(j < files.length)
      (j)->
        file = files[j]
        p = When.sequence([
          ->
            item().then (v)-> When(v).delay(1).then (v)->
              console.log "##{v} reading file with promise: `#{file}`"
              readFileP(path.join(jspath, file), 'utf8').then (res)->
                fileTxt = res

          ->
            item().then (v)-> When(v).delay(1).then (v)->
              console.log "##{v} parsing file: `#{file}`"
              for i in [1..10]
                ast = esprima.parse(fileTxt)
              console.log fileTxt[1..100], ast.type
        ])

        console.log 'registering catch #', catchCount++
        p.catch (err)->
          l.error "An error was caught:", err
          process.exit 1
    ,0)
,0)

The last lines of the outcome are

....
#56 reading file with promise: `lodash.js`
#56 parsing file: `lodash.js`
**
 * @license
 * Lo-Dash 2.4.1 <http://lodash.com/>
 * Copyright 2012-2013 The Dojo Foundation <htt Program
 registering catch # 392
#57 reading file with promise: `dist/lodash.compat.js`
#57 parsing file: `dist/lodash.compat.js`
**
 * @license
 * Lo-Dash 2.4.1 (Custom Build) <http://lodash.com/>
 * Build: `lodash -o ./dist/loda Program
 registering catch # 393
Potentially unhandled rejection [1] TypeError: object is not a function
  at Promise._beget (E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\makePromise.js:166:16)
  at Promise.then (E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\makePromise.js:140:17)
  at Promise.catch (E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\makePromise.js:156:16)
  at Promise.catch.Promise.otherwise (E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\decorators\flow.js:37:22)
  at E:\dev\uBerscore\node_modules\urequire\DRAFT\whentest.coffee:58:13
  at next (E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\decorators\iterate.js:57:20)
  at E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\decorators\array.js:35:24
  at tryCatchReject (E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\makePromise.js:830:30)
  at runContinuation1 (E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\makePromise.js:789:4)
  at Fulfilled.when (E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\makePromise.js:580:4)
  at Pending.run (E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\makePromise.js:471:13)
  at Scheduler._drain (E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\Scheduler.js:62:19)
  at Scheduler.drain (E:\dev\uBerscore\node_modules\urequire\node_modules\when\lib\Scheduler.js:27:9)
  at process._tickCallback (node.js:419:13)

#57 reading file with promise: `dist/lodash.compat.min.js`
#57 parsing file: `dist/lodash.compat.min.js`
**
 * @license
 * Lo-Dash 2.4.1 (Custom Build) lodash.com/license | Underscore.js 1.5.2 underscorejs Program 

[unscriptable]

Yes, this looks like the same issue as #345.

[unscriptable]

Hey @anodynos, can you paste the generated javascript perchance?

[briancavalier]

Wow, I really appreciate your putting together a test for this! Could you put the generated JS in a gist?

[briancavalier]

lol, jinx @unscriptable :)

[anodynos]

You're welcome @briancavalier, glad to help. https://gist.github.com/anodynos/2e113eace0001a4a5748 (you really need to catch up with coffeescript ;})

Note: you don't need 30 iterations of esprima.parse, 10 will do ! But with 5 it will not throw - go figure! Somehow my trust on the nodejs platform is hindered...

[briancavalier]

Thanks for gisting the JS :) I got the test running locally and, sure enough, it errors in exactly the same spot:

**
 * @license
 * Lo-Dash 2.4.1 (Custom Build) <http://lodash.com/>
 * Build: `lodash -o ./dist/loda Program
registering catch # 393
Potentially unhandled rejection [1] TypeError: object is not a function
    at Promise._beget (/private/tmp/345/node_modules/when/lib/makePromise.js:166:16)

Note: you don't need 30 iterations of esprima.parse, 10 will do ! But with 5 it will not throw

o.O

Somehow my trust on the nodejs platform is hindered...

Yeah, it's a bit unnerving to know the possibility of "randomly invalid compiler output" exists. But I also sympathize ... getting an optimizing compiler right in all cases is probably pretty challenging.

[anodynos]

Update: The magic number of the completely irrelevant parse invocations is 7. Like the 7 deadly sins. With 6, is doesn't throw on 393. With >=7 it does!

[anodynos]

Yeah, it's a bit unnerving to know the possibility of "randomly invalid compiler output" exists. But I also sympathize ... getting an optimizing compiler right in all cases is probably pretty challenging.

I understand that, but I can't rationalize is why it fails at the n-th iteration, and not the n-1. Surely the (erroneous) compilation takes place only once, not at every loop. I think this needs to be escalated to the nodejs/V8 guys...

[anodynos]

The

Promise.prototype._beget = function() {
   try {} finally {};
...

seems to work well with this code, although I'm sure I had problems even with that on last night.

[briancavalier]

@anodynos Ok, yeah, if you can try to verify that, it will help because I'm about to file a v8 bug :) See: https://github.com/briancavalier/when-v8-invalid-optimization

[briancavalier]

Surely the (erroneous) compilation takes place only once, not at every loop

I'm not sure either, but it may have to do with v8 detecting hot paths after some number of executions. For example, iteration 393 may mean that _beget has be executed enough times (probably way more than 393 times) to cross v8's threshold for being considered for optimization. At that point, the newly optimized and invalid _beget code executes and fails. It's a theory anyway :)

[anodynos]

I'm not sure either, but it may have to do with v8 detecting hot paths after some number of executions. For example, iteration 393 may mean that _beget has be executed enough times (probably way more than 393 times) to cross v8's threshold for being considered for optimization. At that point, the newly optimized and invalid _beget code executes and fails. It's a theory anyway :)

Well, with an earlier configuration of that code (and a bit more complex, with classes and binding contexts) I was consistently getting it at 192 :-/

Regarding try {} finally {} it seems ok, but I am sure I got an error at least once yesterday...

Its so arbitrary, its scary... The V8 needs to hammer this...

[briancavalier]

Bug report filed: https://code.google.com/p/v8/issues/detail?id=3692

Star it up :)

[anodynos]

+1 starred

[briancavalier]

If I change _beget in master to the following, the failure seems to go away:

        Promise.prototype._beget = function() {
            return begetFrom(this._handler, this.constructor);
        };

        function begetFrom(parent, Promise) {
            var child = new Pending(parent.receiver, parent.join().context);
            return new Promise(Handler, child);
        }

It's running on my machine right now, and passed 3500 iterations.

Can you try that same change and let me know?

UPDATE: Yep, it successfully completed 7000 iterations (using the magic number 7, as above) and exited.

[anodynos]

Maybe we need to leave it running a whole night ?

[briancavalier]

It certainly can't hurt :) I can do that tonight.

This comment on the bug report has me a little worried. It seems to indicate that there is no support for any version of v8 in any currently released version of node. That makes it sound as if there simply is no recourse for any bug found in v8 that might affect an in-production system. I must be misreading it ...

Perhaps the node team supports those versions?

[anodynos]

It's evident that the nodejs people should get the bug report - if might certainly affect many production systems out there...

[briancavalier]

@anodynos See #404 ... discovered some more interesting things, with help from @spion on irc.

[anodynos]

I reproduced the error @ 393 (on Kubuntu 14x64, using magic numba 15) with: 3.4.0, 3.4.1, 3.4.2, 3.5.0, 3.5.1, 3.5.2

Especially with when@3.4.0 & @3.4.1 it failed silently without throwing any errors, i.e

registering catch # 393
#57 reading file with promise: `dist/lodash.compat.min.js`
#57 read file: `dist/lodash.compat.min.js`
#57 parsing file: `dist/lodash.compat.min.js`

and it stops.

With @3.3 the test wont run at all:

registering catch # 0
#1 reading file with promise: `dist/lodash.compat.js`

and it stops - didn't bother to see why.

This is such a deal breaker, it breaks my urequire code that was about to be released :-( I 'll try the patch version and let you know...

[briancavalier]

@anodynos Sorry this is holding up your release. I'm hoping to get #404 merged asap and release 3.6.2, hopefully tomorrow. If the patched version works for you then hopefully 3.6.2 will unblock your urequire release.

[anodynos]

Cool, thanks @briancavalier for your immediate response and remarkable commitment :-) I 've got to 32002 iterations, I think its as solid as it can get :-)

[briancavalier]

I 've got to 32002 iterations

Awesome :) Yep, it's looking good.

[anodynos]

I got to ~130K iterations on Windows 7x64 & Kubuntu with 3.6.2

[briancavalier]

woot. I just killed my overnight run at ~160k. I think it's time for a release :)

[briancavalier]

3.6.2 just landed.

@anodynos Thanks for your above-and-beyond help on this! Without it, I'm sure we would have been battling this issue for much, much longer.

[anodynos]

Thanks @briancavalier, I'm very glad I helped and we got to nail it :-)

Lets make sure we escalate the nasty V8 bug to the nodejs team & community, cause no one knows where it'll hit next. People might loose their sleep & counteless hours cause of this, blaming themselves or their team or some other product etc....

[briancavalier]

@anodynos Yep, I agree. It's on my todo list for today to file the issue with the node team.

The larger issue of the apparent rift between node and v8 is also concerning. I'm not really sure what can be done there. I believe v8 API changes are at least one reason node is still using much older versions of v8. In contrast, Chrome has kept up. Maybe there is a node/v8 cultural divide as well.

I know some work is being done to help isolate node from v8 APIs, which hopefully will help going forward (node 0.12?).

[briancavalier]

@anodynos Took me a little longer than I hoped, but I just filed a bug with node as well: joyent/node#8730

[anodynos]

Nice @briancavalier - its good news its fixed in 0.11.x...