Unexpected recursion when using JS analysis

[LucaFranceschini]

I am trying to track down builtin function invocations with NodeProf. I am running NodeProf directly on GraalVM.

Consider the following program opening a file and then closing it:

const fs = require('fs')

fs.open('out.txt', 'w', (err, fd) => {
    if (!err) fs.close(fd, err => {})
})

And the following simple analysis printing builtinEnter events (written starting from one of the examples):

// DO NOT INSTRUMENT
(function (sandbox) {
  function MyAnalysis() {
    this.builtinEnter = function (name, f, dis, args) {
      console.log("builtinEnter: %s", name);
    };
  }
  sandbox.addAnalysis(new MyAnalysis(), {includes:"<builtin>,enterExit.js,exitException"});
})(J$);

The file program works fine when executed with node, but if I execute it as suggested in the tutorial with the following command:

$ /usr/lib/jvm/java-8-graal/bin/node --jvm --jvm.Dtruffle.class.path.append=../nodeprof.jar --nodeprof ../nodeprof.js/src/ch.usi.inf.nodeprof/js/jalangi.js --analysis ../nodeprof.js/src/ch.usi.inf.nodeprof/js/analysis/enter-exit/myanalysis.js program.js

The program at some point enters an endless recursion:

...
builtinEnter: Reflect.apply
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Reflect.apply
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Reflect.apply
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Reflect.apply
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Reflect.apply
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Reflect.apply
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Reflect.apply
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Reflect.apply
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Number.isSafeInteger
builtinEnter: Reflect.apply
...

What am I missing?

[alexjordan]

Hi Luca,

I can't exactly what triggers the recursion, but the builtin callbacks are tricky to work with. As a workaround, avoid using console.log inside builtinEnter/Exit, e.g. just defer your logging:

// DO NOT INSTRUMENT
(function (sandbox) {
  function MyAnalysis() {
    var builtins = [];
    this.builtinEnter = function (name, f, dis, args) {
      builtins.push(name);
    };
    this.endExecution = function () {
      console.log(builtins);
    }
  }
  sandbox.addAnalysis(new MyAnalysis(), {includes:"<builtin>,enterExit.js,exitException"});
})(J$);  

[Haiyang-Sun]

@alexjordan is right. The cause is about console.log. Although we have some bypass mechanism to avoid recursively instrumenting the code inside the Jalangi analysis, console.log internally uses process.nextTick to run some I/O in the next event loop which will use some built-in functions which triggers the built-in callback and results in an infinite recursion.

I will post a patch later today to solve this problem which can give you the ability to dump logs inside the builtin callback.

[LucaFranceschini]

Thanks both of you for your prompt replies and patch!