bytenode/bytenode

compiledWrapper.apply is not a function

s100 opened this issue · 10 comments

s100 commented

This is Node.js v10.16.0 on Windows 10 64-bit. We also see this on Node.js v10.16.2 on Linux 64-bit.

This is a really puzzling and intermittent error and I must apologise but it's been very difficult to come up with consistent steps to reproduce it. I feel as if the problem may be environmental but there are aspects of how bytenode works which I do not understand so I'm not sure what kind of environmental issue could be causing this, which is why I'm reaching out for help. Here's the minimal scenario I've managed to concoct:

src/main.js:

console.log('hello world')

build/build.js (this consumes src/main.js and outputs dist/main.jsc):

const bytenode = require('bytenode')
const fsExtra = require('fs-extra')
const tmp = require('tmp')

fsExtra.removeSync('./dist')
fsExtra.ensureDirSync('./dist')

const source = fsExtra.readFileSync('./src/main.js')

const tmpFile = tmp.fileSync()
fsExtra.writeFileSync(tmpFile.name, source)

bytenode.compileFile({
  filename: tmpFile.name,
  compileAsModule: true,
  output: './dist/main.jsc'
})

dist/main.jsc is about 1kB of bytecode, of course, and I can't attach it, but here's the Base64 for it if that's any use:

tQPewIr01PReAAAA/wMAAOyrzzQGAAAAAAAAAGgDAAC6UcawNe4pcAAAAIAgAACAwAQAgAAAAIAAAACAAAAAgAIskwIkFsjAAAAAAAgAAAACDIzAAAAAAAEAAAACLJMCLPDAAAAAABcAAAACFIzAAAAAAAMAAAACEJHCutOeVQAAAAAAAAAABwAAAGNvbnNvbGUAAhCRwobZQrcAAAAAAAAAAAMAAABsb2cAAAAAAAIUkcP+HxH6AAAAAAAAAAALAAAAaGVsbG8gd29ybGQAAAAAAAIIi8AAAAAAAAAAAAIQi8IAAAAACgAAAAEWAmgLEBUADCoAAAAAAADFGAAAADAAAAAAAAAAAEACAAAAoBMAACb6KPoBAib7EgIm+Vf7+vkEDaQAAAAAAAAAAkSSxAAAAAAPAAAAAAAAAMFdAAAAAAAABQAAAAAAAAAAAAAAAAAAAAAAAAACEJHCLvpbsAAAAAAAAAAABwAAAGV4cG9ydHMAAhCRwp7Ws14AAAAAAAAAAAcAAAByZXF1aXJlAAIQkcLSPVIMAAAAAAAAAAAGAAAAbW9kdWxlAAACFJHDlgXFAgAAAAAAAAAACgAAAF9fZmlsZW5hbWUAAAAAAAACFJHDUlynEgAAAAAAAAAACQAAAF9fZGlybmFtZQAAAAAAAADAAAAAAAAAAACJwAAAAAD/////hMEAAAAACgAAAAAAAABcAAAAAggWuMAGAAAABhRAAAJEFs0HFwACGJHEIpY3ZQAAAAAAAAAAFwAAAGV2YWxtYWNoaW5lLjxhbm9ueW1vdXM+AMEAAAAAAAAAAAAAAAAAAAAAhODAAAAAAAIAAACEwAAAAACHAAAAhMAAAAAAAAAAAAEQFi0BwAAAAAACAAAAfgoAfgpcwAAAAAACAAAAhOCewAAAAAAEAAAAicMBAAAABQAAAAUAAAAKAAAAKAAAAFwAAAABAAAAAAgAAAIIi8AAAAAAAAAAAAIMi8EAAAAABwAAAAECAgAMugEAwwgAAAAIAAAAAAAAAABAAgAAAKB8AAAAJvukAAAAAAAAAjCSxQAAAAAKAAAAAAAAAEMMAAAAAAAAAAAAAAAAAAABAAAAAAAAAAAAAAAAAAAAAAAAABblA4nCAAAAAP////8AAAAAAAAAAAAAAABeAAAAAgjxwAEAAAASAAAACrkBwAAAAAAEAAAAicMAAAAAAAAAAAAAAAAKAAAAAgAAAF4AAAD/////AAgAABwvLy8vLy8v

index.js (this serves as the entry point):

require('bytenode')
module.exports = require('./dist/main.jsc')

When I run index.js, I get

hello world

Process finished with exit code 0

When I debug index.js (my debugger in this case is WebStorm 2019.2), I get

Debugger listening on ws://127.0.0.1:59811/0c14ba72-bbe5-476b-9ba7-979b3b9a6b03
For help, see: https://nodejs.org/en/docs/inspector
Debugger attached.
C:\Users\...\node_modules\bytenode\index.js:216
  return compiledWrapper.apply(module.exports, args);
                         ^

TypeError: compiledWrapper.apply is not a function
    at Object.Module._extensions.(anonymous function) [as .jsc] (C:\Users\...\node_modules\bytenode\index.js:216:26)
    at Module.load (internal/modules/cjs/loader.js:653:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:593:12)
    at Function.Module._load (internal/modules/cjs/loader.js:585:3)
    at Module.require (internal/modules/cjs/loader.js:690:17)
    at require (internal/modules/cjs/helpers.js:25:18)
    at Object.<anonymous> (C:\Users\...\index.js:2:18)
    at Module._compile (internal/modules/cjs/loader.js:776:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:787:10)
    at Module.load (internal/modules/cjs/loader.js:653:32)
Waiting for the debugger to disconnect...

Process finished with exit code 1

I also see this problem when not debugging, in some scenarios where the bytenoded source is much larger. In this case I find that trying to load the module interactively, e.g.

node
> require('my-module')
TypeError: compiledWrapper.apply is not a function

> require('my-module')
TypeError: compiledWrapper.apply is not a function

causes the compiledWrapper error to repeat on each attempt... but simply exiting the interactive session and running node again can cause the problem to go away semi-permanently.

Closer inspection of Module._extensions[.jsc] indicates that under normal circumstances, the value returned from compiledWrapper = script.runInThisContext(...) is a function, whose string representation is 91 copies of U+200B ZERO WIDTH SPACE in a row. But in the failure case, compiledWrapper is simply a 92-character string consisting of U+200B ZERO WIDTH SPACEs. In both cases length = readSourceHash(bytecodeBuffer) returned 94. A string has no apply method on it, hence the error.

What could be causing this?

OsamaAbbas commented

I could reproduce it using VSCode debugger, only using Node 10.16.x.

Node 12 works properly.

However, I could not reproduce it when running your app interactively (in Node REPL).

Still investigating what could be the cause.

  • 👍2
OsamaAbbas commented

I also see this problem when not debugging, in some scenarios where the bytenoded source is much larger. In this case I find that trying to load the module interactively

Could you please try this scenario with Node 12?

  • 👍2
OsamaAbbas commented

I feel as if the problem may be environmental

The problem happens because the script created by bytenode, here:

let script = new vm.Script(dummyCode, {
    filename: filename,
    lineOffset: 0,
    displayErrors: true,
    cachedData: bytecodeBuffer
  });

does NOT use the cachedData: bytecodeBuffer. So it uses the dummyCode (which is just a string of zero width spaces). The weird thing is that the next line (in bytenode) is:

if (script.cachedDataRejected) {
    throw new Error('Invalid or incompatible cached data (cachedDataRejected)');
  }

so the flag cachedDataRejected was not set to true. I cannot figure out why it is not set to true and why does this happen only in debug mode!

(I tried to run build.js in debug mode. The result is weirder, because the compiled file does not run neither in debug mode or normal mode).

After some searching and digging in v8 source code, I found nothing. But this issue nodejs/node#20052 might be related. It's mentioned in this comment nodejs/node#20052 (comment) that when providing vm.Script with an INVALID cachedData it still runs (using the source code provided) and does NOT set cachedDataRejected to true.

Anyways, the problem now is clear, in Node ≤ 10: Debug mode breaks bytenode (because it uses the empty dummyCode and ignores the compiled version). Until we find a way to fix it, what do you suggest? Is it enough to edit the README and mention this as a 'known issue'?

  • 👍1
s100 commented

Thanks for your work on this. And also thanks for a great piece of software overall, I forgot to mention that!

I could not reproduce it when running your app interactively (in Node REPL).

I saw that problem for a much larger JSC file which contains a much larger quantity (~5MB) of JS. Again, it was annoyingly inconsistent so it's hard to say what the specific issue is.

Could you please try this scenario with Node 12?

With Node.js v12.10.0 I was unable to reproduce this issue. (Although, as I say, because the problem with the larger packages was inconsistent, it's hard to be sure whether it's been resolved completely.) Upgrading from Node.js v10 to v12 is a possibility for us although there are some drawbacks. In any case, we will definitely keep that in mind as a potential workaround.

I think at the very least it would be good to document this problem as a known issue in the README.

The Node.js issue you linked does seem to be related. It would explain all of the behaviour I'm seeing if Node is having intermittent trouble with the cached code we're providing it, but not returning the right cachedDataRejected flag. This could also explain why restarting the node REPL makes the error go away - because the node process has some kind of internal state which is persisting. But without going into the internals of Node.js it's hard to say what the deal is.

I'm going to see if I can pull out some of the internals of bytenode and create an even more minimal demonstration case, which we might be able to share with the Node.js maintainers.

  • 👍1
s100 commented

Well, while trying to pare this down to a simpler case, I have arrived at what could be an unrelated issue where

const Module = require('module')
const v8 = require('v8')
const vm = require('vm')

v8.setFlagsFromString('--no-lazy')

const bytecodeBuffer = new vm.Script(Module.wrap('console.log("hello world")')).createCachedData()

works fine under normal circumstances and returns a sensible Buffer object full of bytecode, but if I try to debug it (in WebStorm 2019.2), the Buffer returned is just plain empty. Sometimes. Something weird is going on with the way cached data is handled inside V8.

  • 👍1
OsamaAbbas commented

My initial guess was that the debug mode has some "flag hash" different than the normal mode. This difference could explain why the normal compiled jsc files can't be debugged. But then I tried to compile in the debug mode itself and nothing worked.

So maybe your last comment is pointing to the other direction: the debug mode in Node ≤ 10 somehow breaks CachedData mechanism.
(Comparing these lines from v10.x with those from v11.x may also supports this hypothesis. I'm not sure that they are related to our issue here)

It's now almost clear that the issue lies in v8 itself, not node internals, and of course not in bytenode. Bytenode is nothing but a very thin layer. Most of bytenode source code is straightforward, the only part that might need to be explained is how we "fix" the bytecode cache (by compiling a very small piece of code, and read its flags, then we use it to pass the sanity checks of v8: see v10.x, v11.x). The differences in this part between Node versions is related to how the data header is defined (which is inaccurate by the way in the comments, we had to read the source code to find the correct order of these bytes).

That being said: we cannot fix our issue WITHOUT changing the v8 source itself. This means that we would have to compile a custom version of Node v10.x (which is against the very idea of bytenode).

However, if you want to do this yourself: it's easier to disable the sanity checks alltogether. This is the approach that NW.js guys followed in their implementation of "nwjc" tool. See here.

Your options now are:

  • Upgrading to Node 12. (It will become an active LTS within a month or so).
  • Compile your own Node v10.x version with sanity checks disabled.
  • File an issue in Node repository so they fix the issue in Node 10.17 or so.

In bytenode, I will edit the README file soon to mention this limitation.

Thank you for your report.

  • 👍1
s100 commented

Alright, well I'm glad the problem isn't in bytenode... thanks for the additional information about how this package works internally. And thank you very much for the suggestions about chasing this problem down. I will see about raising an issue for Node and/or V8 and I'll take a look at the nwjc tool you mentioned as well. Thank you for your help. :)

  • 👍2
OsamaAbbas commented

Thank you for you kind words. Sorry I could not solve it. Hope you can find a suitable workaround.

caihaibin1991 commented

I have solved this problem.
keep js and jsc on the same place. and require('xxxx.js') modify to be require('xxxx'). when you develp or debug, the system will load js file, when you offer the code to other computer, you just remove js file, the system will be automatic to load jsc file. you can run them in nodejs 10.xxx.

caihaibin1991 commented

use this way, when develp, the editor can show the tip normally. It is very useful