Node 11.4.0+ fails to resolve index.js when combined with -r and --inspect-brk

[jdalton]

index.js

console.log("hi from index.js")

preload.js

console.log("hi from preload.js")

In Node 11.3.0 and below this works:

node -r ./preload.js --inspect-brk index.js

and results in:

Debugger listening on ws://127.0.0.1:9229/3a4d89ae-03a7-45f0-b740-711ac3fb490e
For help, see: https://nodejs.org/en/docs/inspector
Debugger attached.
hi from preload.js

However, in Node 11.4.0+ it errors with:

Debugger listening on ws://127.0.0.1:9229/d9fa3f56-312d-4288-a61c-9eb221c0ad02
For help, see: https://nodejs.org/en/docs/inspector
Debugger attached.
internal/modules/cjs/loader.js:605
    throw err;
    ^

Error: Cannot find module 'index.js'
    at Function.Module._resolveFilename (internal/modules/cjs/loader.js:603:15)
    at Module._compile (internal/modules/cjs/loader.js:702:31)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Module.require (internal/modules/cjs/loader.js:659:17)
    at Module._preloadModules (internal/modules/cjs/loader.js:844:12)
    at prepareUserCodeExecution (internal/bootstrap/node.js:297:7)
    at startExecution (internal/bootstrap/node.js:275:5)
Waiting for the debugger to disconnect...

[Trott]

Using ./index.js on the command line instead of index.js will make it work.

node -r ./preload.js --inspect-brk ./index.js

Not suggesting that requiring ./ to start the path is OK or anything. Just offering it up in case it helps someone track what's gone wrong here.

[jdalton]

I narrowed the problem commit down to 7b8058a. (PR #24673)

[Trott]

@joyeecheung

[richardlau]

Some further debugging (using fixtures in test/fixtures):
Node.js 11.3.0:

-bash-4.2$ NODE_DEBUG=module ~/sandbox/bin/node-v11.3.0-linux-x64/bin/node -r ./test/fixtures/printA.js --inspect-brk test/fixtures/printB.js
Debugger listening on ws://127.0.0.1:9229/a571afd0-a45a-4967-afcd-803c67935e27
For help, see: https://nodejs.org/en/docs/inspector
Debugger attached.
MODULE 3872: Module._load REQUEST ./test/fixtures/printA.js parent: internal/preload
MODULE 3872: looking for "./test/fixtures/printA.js" in [".","/home/users/riclau/sandbox/github/nodejs/node_modules","/home/users/riclau/sandbox/github/node_modules","/home/users/riclau/sandbox/node_modules","/home/users/riclau/node_modules","/home/users/node_modules","/home/node_modules","/node_modules","/home/users/riclau/.node_modules","/home/users/riclau/.node_libraries","/home/users/riclau/sandbox/bin/node-v11.3.0-linux-x64/lib/node"]
MODULE 3872: load "/home/users/riclau/sandbox/github/nodejs/test/fixtures/printA.js" for module "/home/users/riclau/sandbox/github/nodejs/test/fixtures/printA.js"
MODULE 3872: looking for "/home/users/riclau/sandbox/github/nodejs/test/fixtures/printB.js" in ["/home/users/riclau/.node_modules","/home/users/riclau/.node_libraries","/home/users/riclau/sandbox/bin/node-v11.3.0-linux-x64/lib/node"]
A
MODULE 3872: looking for "/home/users/riclau/sandbox/github/nodejs/test/fixtures/printB.js" in ["/home/users/riclau/.node_modules","/home/users/riclau/.node_libraries","/home/users/riclau/sandbox/bin/node-v11.3.0-linux-x64/lib/node"]
MODULE 3872: load "/home/users/riclau/sandbox/github/nodejs/test/fixtures/printB.js" for module "."
Debugger listening on ws://127.0.0.1:9229/a571afd0-a45a-4967-afcd-803c67935e27
For help, see: https://nodejs.org/en/docs/inspector
B
-bash-4.2$

Node.js 11.4.0:

-bash-4.2$ NODE_DEBUG=module ~/sandbox/bin/node-v11.4.0-linux-x64/bin/node -r ./test/fixtures/printA.js --inspect-brk test/fixtures/printB.js
Debugger listening on ws://127.0.0.1:9229/d94d4c67-1d63-4c79-b6e0-c6cd5c4789dc
For help, see: https://nodejs.org/en/docs/inspector
Debugger attached.
MODULE 868: Module._load REQUEST ./test/fixtures/printA.js parent: internal/preload
MODULE 868: looking for "./test/fixtures/printA.js" in [".","/home/users/riclau/sandbox/github/nodejs/node_modules","/home/users/riclau/sandbox/github/node_modules","/home/users/riclau/sandbox/node_modules","/home/users/riclau/node_modules","/home/users/node_modules","/home/node_modules","/node_modules","/home/users/riclau/.node_modules","/home/users/riclau/.node_libraries","/home/users/riclau/sandbox/bin/node-v11.4.0-linux-x64/lib/node"]
MODULE 868: load "/home/users/riclau/sandbox/github/nodejs/test/fixtures/printA.js" for module "/home/users/riclau/sandbox/github/nodejs/test/fixtures/printA.js"
MODULE 868: looking for "test/fixtures/printB.js" in ["/home/users/riclau/.node_modules","/home/users/riclau/.node_libraries","/home/users/riclau/sandbox/bin/node-v11.4.0-linux-x64/lib/node"]
internal/modules/cjs/loader.js:605
    throw err;
    ^

Error: Cannot find module 'test/fixtures/printB.js'
    at Function.Module._resolveFilename (internal/modules/cjs/loader.js:603:15)
    at Module._compile (internal/modules/cjs/loader.js:702:31)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Module.require (internal/modules/cjs/loader.js:659:17)
    at Module._preloadModules (internal/modules/cjs/loader.js:844:12)
    at prepareUserCodeExecution (internal/bootstrap/node.js:297:7)
    at startExecution (internal/bootstrap/node.js:275:5)
Waiting for the debugger to disconnect...
-bash-4.2$

In 11.3.0 test/fixtures/printB.js is fully resolved (/home/users/riclau/sandbox/github/nodejs/test/fixtures/printA.js) but in 11.4.0 it remains relative. I'm not sure what in 7b8058a is causing this -- Perhaps some side effect of preloading (the commit changes the preloading of modules to occur before process.argv[1] is resolved)?

The following testcase fails when run with Node.js v11.4.0 and passes with v11.3.0 (I have it in test/sequential with all the other inspector tests but I see no reason for it not to live in test/parallel (the port used is different each time):

// Flags: --expose-internals
'use strict';

const common = require('../common');
common.skipIfInspectorDisabled();
const { path: fixture } = require('../common/fixtures');

const { NodeInstance } = require('../common/inspector-helper.js');
const assert = require('assert');
const { join, relative } = require('path');

async function runTest() {
  // Script argument should be relative (https://github.com/nodejs/node/issues/25967)
  const child = new NodeInstance(
      ['-r', fixture('printA.js'), '--inspect-brk=0'],
      null,
      relative(join(__dirname, '..', '..'), fixture('printB.js'))
    );

  const session = await child.connectInspectorSession();

  const commands = [
    { 'method': 'Runtime.enable' },
    { 'method': 'Runtime.runIfWaitingForDebugger' }
  ];

  session.send(commands);
  for (const expected of ['A', 'B']) {
    const msg = await session.waitForNotification('Runtime.consoleAPICalled');
    assert.strictEqual(msg.params.type, 'log');
    assert.deepStrictEqual(msg.params.args, [{
      type: 'string',
      value: expected
    }]);
  }
  session.disconnect();
}

runTest();

[jdalton]

@richardhoehn I found the issue. Before 7b8058a there was this

// Make process.argv[1] into a full path.
const path = NativeModule.require('path');
process.argv[1] = path.resolve(process.argv[1]);

const CJSModule = NativeModule.require('internal/modules/cjs/loader');

preloadModules();

after it is:

function prepareUserCodeExecution() {
  // If this is a worker in cluster mode, start up the communication
  // channel. This needs to be done before any user code gets executed
  // (including preload modules).
  if (process.argv[1] && process.env.NODE_UNIQUE_ID) {
    const cluster = NativeModule.require('cluster');
    cluster._setupWorker();
    // Make sure it's not accidentally inherited by child processes.
    delete process.env.NODE_UNIQUE_ID;
  }

  // For user code, we preload modules if `-r` is passed
  // TODO(joyeecheung): use internal/options instead of
  // process._preload_modules
  if (process._preload_modules) {
    const {
      _preloadModules
    } = NativeModule.require('internal/modules/cjs/loader');
    _preloadModules(process._preload_modules);
  }
}

So it's missing setting

// Make process.argv[1] into a full path.
const path = NativeModule.require('path');
process.argv[1] = path.resolve(process.argv[1]);

I manually patched this in and can confirm it fixed the issue.

function prepareUserCodeExecution() {
  // Make process.argv[1] into a full path.
  const path = NativeModule.require('path');
  process.argv[1] = path.resolve(process.argv[1]);

[joyeecheung]

@jdalton process.argv[1] is still normalized, but the order was changed in 7b8058a and the normalization was done after -r is handled so I think moving that somewhere earlier should fix the issue - however it's not entirely clear to me where this should be done on master (ideally things like this should happen as late as possible). It's probably fine to do it when preparing user code execution in all execution modes where -r is handled.

I could fix it as part of #26000 but v11 would need a separate change before other refactorings are backported if it's urgent.

[jdalton]

Since it's a regression from all earlier (pre 11.4.0) supported Node versions it'd be great to have this fixed for 11.x. and 12. A fix in #26000 for v12 and then another one-off for Node 11.x?

[joyeecheung]

@jdalton Fixing it ad-hoc on v11-staging right now may interfere with backports of other pending backports to v11.x-staging e.g. this would be in conflict with #25667 so it depends on how urgent this is and whether it is worth the conflict I guess. At least for now the branch only gets hit when --inspect-brk is used and there is a workaround (#25967 (comment)).

[jdalton]

Fixing it ad-hoc on v11-staging right now may interfere with backports of other pending backports to v11.x-staging

Would fixing it after the pending backports to v11 be an option? I don't see it as urgent enough to complicate pending things but would be nice to have at some 11.x.

Update:

Fix for Node 12 landed as 69714ab.