node icon indicating copy to clipboard operation
node copied to clipboard

Console logs from module loader hooks worker are not printed

Open uhyo opened this issue 1 year ago • 0 comments

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.

uhyo avatar Feb 05 '24 13:02 uhyo