Console logs from module loader hooks worker are not printed

[uhyo]

Version

v20.11.0

Platform

Linux Lenovo-X13 5.15.133.1-microsoft-standard-WSL2 #1 SMP Thu Oct 5 21:02:42 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Subsystem

module

What steps will reproduce the bug?

index.mjs:

// graphql is not related to the issue. This is just a random example of middle-sized CommonJS package
import graphql from "graphql";

hooks.mjs:

import { readFile } from "fs/promises";

export async function resolve(specifier, context, defaultResolve) {
  const result = await defaultResolve(specifier, context);
  console.log("resolve", specifier);
  return result;
}

export async function load(url, context, nextLoad) {
  const result = await nextLoad(url, context);
  if (result.format === "commonjs") {
    // This seems the way to opt into the new CJS loader
    result.source ??= await readFile(
      new URL(result.responseURL ?? url),
      "utf-8"
    );
  }
  console.log("load", context);
  return result;
}

command to run:

node --import 'data:text/javascript,import { register } from "node:module"; import { pathToFileURL } from "node:url"; register("./hooks.mjs", pathToFileURL("./"));' ./main.mjs

How often does it reproduce? Is there a required condition?

Always

What is the expected behavior? Why is that the expected behavior?

All logs produced by the console.log calls in hooks.mjs should be printed to the console that runs node.

What do you see instead?

Only a small part of logs are printed. Below is the entirety of the logs that reached the console. Actually, many more logs have been printed by the hooks.

resolve file:///home/uhyo/repos/nodejs-hooks-perf/main.mjs
load { format: 'module', importAttributes: {} }
resolve graphql
load { format: 'commonjs', importAttributes: {} }

Additional information

Apparently, logs that aren't shown are ones that are produced during the hooks worker processes CJS -> CJS require calls. In other words, when the main thread is communicating synchronously with the worker, logs fail to reach the screen.

This reminds me of Synchronous blocking of stdio documented in the Worker API reference. In the case of module loader hooks, the main process seems to shut down before the logs have chance to get to the screen.

I spent several hours figuring out this why module loader hooks weren't emitting any logs. Improvement would be helpful a lot.

[Griffork]

Can confirm this is also happening on Windows.

[RedYetiDev]

I've been unable to reproduce (on Node.JS v22):

└─$ node --import 'data:text/javascript,import { register } from "node:module"; import { pathToFileURL } from "node:url"; register("./hooks.mjs", pathToFileURL("./"));' ./main.mjs
resolve file:///█████████████████/node/testing/main.mjs
load { format: 'module', importAttributes: {} }
resolve fs
load { format: 'builtin', importAttributes: {} }

[uhyo]

@RedYetiDev Thanks for looking into it, but I did reproduce this in v22.1.0.

You can try below code to see the issue more clearly. Below code emits logs to the console and a file simulnateously. You should see that only 4 lines are printed to the console, while much more lines are written in ./log.

Also you seem to have replaced graphql with fs, but doing so hides the issue because fs is a built-in module. You need to import a third-party multi-file package written in CJS to reproduce the issue. (the point is to prepare a module graph of form ESM → CJS → CJS so you could prepare multile CJS files locally, but I'd assume this is more burdening than installing a random external package)

hooks.mjs:

import { inspect } from "util";
import { readFile } from "fs/promises";
import { appendFileSync } from "fs";

export async function resolve(specifier, context, defaultResolve) {
  const result = await defaultResolve(specifier, context);
  console.log("resolve", specifier);
  appendFileSync("./log", `resolve ${specifier}\n`);
  return result;
}

export async function load(url, context, nextLoad) {
  const result = await nextLoad(url, context);
  if (result.format === "commonjs") {
    // This seems the way to opt into the new CJS loader
    result.source ??= await readFile(
      new URL(result.responseURL ?? url),
      "utf-8"
    );
  }
  console.log("load", context);
  appendFileSync("./log", `load ${inspect(context)}\n`);
  return result;
}

[RedYetiDev]

Thanks! I'll test again later today, using your code with graphql

[RedYetiDev]

I've been able to reproduce now. I'll look into the cause, thanks for the bug report!

[JakobJingleheimer]

This is known and documented: https://nodejs.org/docs/latest/api/module.html#hooks

The hooks thread may be terminated by the main thread at any time, so do not depend on asynchronous operations (like console.log) to complete.