Strange name-changing behaviour in console.log.bind

[empyrical]

This is something I've noticed when using the latest version (4.0.0 as of writing this), and haven't tried it in earlier versions yet.

If you call bind() on console.log, it will modify the name of the original function and also keep tacking on bound to the name every time you call it.

REPL example:

> console.log
[Function: bound ]
> console.log.bind(console)
[Function: bound bound ]
> console.log.bind(console)
[Function: bound bound bound ]
> console.log.bind(console)
[Function: bound bound bound bound ]
> console.log.bind(console)
[Function: bound bound bound bound bound ]
> console.log.bind(console)
[Function: bound bound bound bound bound bound ]
> console.log.bind(console)
[Function: bound bound bound bound bound bound bound ]
> console.log.bind(console)
[Function: bound bound bound bound bound bound bound bound ]
> console.log.bind(console)
[Function: bound bound bound bound bound bound bound bound bound ]

It also will modify the names of the other console functions too:

> console
Console {
  log: [Function: bound bound bound bound bound bound bound bound bound ],
  info: [Function: bound bound bound bound bound bound bound bound bound ],
  warn: [Function: bound bound bound bound bound bound bound bound bound ],
  error: [Function: bound bound bound bound bound bound bound bound bound ],
  dir: [Function: bound bound bound bound bound bound bound bound bound ],
  time: [Function: bound bound bound bound bound bound bound bound bound ],
  timeEnd: [Function: bound bound bound bound bound bound bound bound bound ],
  trace: [Function: bound bound bound bound bound bound bound bound bound ],
  assert: [Function: bound bound bound bound bound bound bound bound bound ],
  Console: [Function: Console] }

And this behaviour doesn't seem to show up for other functions:

> let test = ()=>{}
undefined
> test.bind(null)
[Function: bound ]
> test.bind(null)
[Function: bound ]
> test.bind(null)
[Function: bound ]
> test.bind(null)
[Function: bound ]

[brycebaril]

Appears to be new to 4.0.0

bryce@x1c:~$ node -v
v4.0.0
bryce@x1c:~$ node
> console.log
[Function: bound ]
> console.log.bind(console)
[Function: bound bound ]
> console.log.bind(console)
[Function: bound bound bound ]
> console.log.bind(console)
[Function: bound bound bound bound ]
> console.log.bind(console)
[Function: bound bound bound bound bound ]
> console.log.bind(console)
[Function: bound bound bound bound bound bound ]
>
bryce@x1c:~$ 
bryce@x1c:~$ sudo n 0.12.7
bryce@x1c:~$ node -v
v0.12.7
bryce@x1c:~$ node
> console.log
[Function]
> console.log.bind(console)
[Function]
> console.log.bind(console)
[Function]
>
bryce@x1c:~$ 
bryce@x1c:~$ sudo n io 3.3.0
bryce@x1c:~$ node -v
v3.3.0
bryce@x1c:~$ node
> console.log
[Function]
> console.log.bind(console)
[Function]
> console.log.bind(console)
[Function]
> 

[brycebaril]

This is not unique to console.log

bryce@x1c:~$ node -v
v4.0.0
bryce@x1c:~$ node
> function noop() {}
undefined
> noop.bind(null)
[Function: bound noop]
> noop
[Function: noop]
> noop.bind(null)
[Function: bound noop]
> var bar = noop.bind(null)
undefined
> bar
[Function: bound noop]
> bar.bind(null)
[Function: bound bound noop]
> bar.bind(null)
[Function: bound bound bound noop]
> bar.bind(null)
[Function: bound bound bound bound noop]
> bar.bind(null)
[Function: bound bound bound bound bound noop]
> bar.bind(null)
[Function: bound bound bound bound bound bound noop]

[brycebaril]

Appears to be a V8 "feature"

[chrisdickinson]

Odd that it modifies the original function.

[rvagg]

Indeed, I think this is the crux of the problem, if there is one, for us:

> console
Console {
  log: [Function: bound bound bound bound bound bound bound bound bound ],
  info: [Function: bound bound bound bound bound bound bound bound bound ],
  warn: [Function: bound bound bound bound bound bound bound bound bound ],
  error: [Function: bound bound bound bound bound bound bound bound bound ],
  dir: [Function: bound bound bound bound bound bound bound bound bound ],
  time: [Function: bound bound bound bound bound bound bound bound bound ],
  timeEnd: [Function: bound bound bound bound bound bound bound bound bound ],
  trace: [Function: bound bound bound bound bound bound bound bound bound ],
  assert: [Function: bound bound bound bound bound bound bound bound bound ],
  Console: [Function: Console] }

that's not right, although I do appreciate the bound bound bound for functions that are actually new bound functions

[brycebaril]

Interestingly enough it doesn't seem to happen outside the repl

bryce@x1c:~$ node
> .load t.js
> "use strict";
'use strict'
> function noop() {}
undefined
> var bar = noop.bind(null)
undefined
> for (var i = 0; i < 1e5; i++) {
...   let a = bar.bind(null) // silence!
... }
undefined
> console.log(bar.toString().length)
600039
undefined
> bryce@x1c:~$ node t.js
35

[brycebaril]

The reason it messes up the other names is it breaks the naming for any bound funciton. This V8 feature appears to just be broken:

> function a() { console.log('a') }
undefined
> function b() { console.log('b') }
undefined
> var aa = a.bind(null)
undefined
> aa()
a
undefined
> aa.bind(null)
[Function: bound bound a]
> aa()
a
undefined
> aa.bind(null)
[Function: bound bound bound a]
> aa.bind(null)
[Function: bound bound bound bound a]
> aa.bind(null)
[Function: bound bound bound bound bound a]
> var bb = b.bind(null)
undefined
> bb()
b
undefined
> aa
[Function: bound b]
> aa()
a
undefined

[targos]

This issue is fixed in V8 4.6. Here is the V8 bug: https://code.google.com/p/v8/issues/detail?id=4278

[rvagg]

a candidate for backporting to v4 perhaps; anybody got ideas on how this could end up being a serious bug or is it likely to simply be an annoyance?

[brycebaril]

@rvagg the only case I've heard of this being an issue (so far) is with an APM vendor which was using function.name which is now completely unreliable.

[rvagg]

right, that sucks, unless there's a decent workaround then I'd be +1 on backporting the fix

[wraithan]

This would technically affect us in some cases, even if fixed, because we were relying Function.name to be a valid name to use to name a function. But this makes the bug worse because even more things are being prefixed. We'll be putting a mitigation into our agent since we don't like to caveat our version support but I'm very +1 on backporting the fix from a 'this is the unification, we should look good' perspective.

[lykkin]

It seems as though there are some interesting interactions between binding and console.log

Running:

function fn() {}

var b = fn.bind(null)
process._rawDebug('_rawDebug:',  b.name)
console.log('console.log:', b.name)

fn.bind(null)
process._rawDebug('_rawDebug:', b.name)
console.log('console.log:', b.name)

outputs:

_rawDebug: bound fn
console.log: bound
_rawDebug: bound fn
console.log: bound fn

Note this occurs after any call into console.log, as:

function fn() {}

var b = fn.bind(null)
process._rawDebug('_rawDebug:',  b.name)
console.log('break the binds')
process._rawDebug('_rawDebug:',  b.name)

outputs:

_rawDebug: bound fn
break the binds
_rawDebug: bound

[mscdex]

@lykkin I can't reproduce what you're describing/showing on the master branch.

[wraithan]

@mscdex interesting! 4.0 is the only one we were able to reproduce it on, didn't have a fresh build of master to try it out on. Also they only happened in a file, not in the REPL. (@lykkin and I are co-workers)

[mscdex]

@wraithan Ok, I was trying it from the REPL. It does indeed happen when loaded from a file.

[targos]

#2916

[wraithan]

Confirmed that @targos's backport PR #2916 fixes the issue that @lykkin brought up

Input:

function fn() {}

var b = fn.bind(null)
process._rawDebug('_rawDebug:',  b.name)
console.log('console.log:', b.name)

fn.bind(null)
process._rawDebug('_rawDebug:', b.name)
console.log('console.log:', b.name)

Output:

_rawDebug: bound fn
console.log: bound fn
_rawDebug: bound fn
console.log: bound fn

[targos]

Fixed by d7da617 and released in v4.1.0