Unactionable "Label ... already exists for debuglog.time" warning since Node.js 22.6

Version

22.6.0

Platform

This is also happening on Windows/Linux/MacOS on GitHub actions.

Linux ... 6.9.3-76060903-generic #202405300957~1718348209~22.04~7817b67 SMP PREEMPT_DYNAMIC Mon J x86_64 x86_64 x86_64 GNU/Linux

Subsystem

modules or diagnostics channel

What steps will reproduce the bug?

I apologize because I don't actually have any steps to reproduce this, other than "run https://github.com/babel/babel 's tests on GitHub actions" and I know that this is not enough info. My hope is that by opening this issue somebody can help me figuring out how to create a reproduction.

See #54265 (comment)

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

Always

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

/

What do you see instead?

Since the 22.6 release, we started seeing some warnings in Babel's CI like the following:

    (node:2812) Warning: Label '[/home/runner/work/babel/babel/packages/babel-core/lib/config/files/module-types.js] [/tmp/babel-process-test/e32882efec210f33a8cfdd13fee63ad22c2590c7/babel.config.js]' already exists for debuglog.time

# With manual line breaks, since scrolling code blocks on GitHub is annoying:

(node:2812) Warning: Label '[/home/runner/work/babel/babel/packages/babel-core/lib/config/files/module-types.js]
 [/tmp/babel-process-test e32882efec210f33a8cfdd13fee63ad22c2590c7/babel.config.js]' already exists for
 debuglog.time

We caught it because it's happening in a test where we spawn a Node.js process and check the stderr.

If I run with --trace-warnings, I get this trace:

    (node:2544) Warning: Label '[/Users/runner/work/babel/babel/packages/babel-core/lib/config/files/module-types.js] [/private/var/folders/m_/cksx93ys47x4621g0zbw_m4m0000gn/T/babel-process-test/be7eb1bfb608a11851acddc4b71f6a214918b8a4/babel.config.js]' already exists for debuglog.time
        at time (node:internal/util/debuglog:230:13)
        at internalStartTimer (node:internal/util/debuglog:400:5)
        at wrapModuleLoad (node:internal/modules/cjs/loader:214:3)
        at Module.require (node:internal/modules/cjs/loader:1339:12)
        at fn (node:internal/modules/helpers:125:16)
        at startHiding - secret - don't use this - v1 (/Users/runner/work/babel/babel/packages/babel-core/src/errors/rewrite-stack-trace.ts:113:14)
        at loadCjsDefault (/Users/runner/work/babel/babel/packages/babel-core/src/config/files/module-types.ts:52:41)
        at loadCodeDefault (/Users/runner/work/babel/babel/packages/babel-core/src/config/files/module-types.ts:110:18)
        at loadCodeDefault.next (<anonymous>)
        ...

Additional information

From that trace, it seems like the warning is not coming from a label that we create in our code, but from a label that Node.js creates internally (and this is why I believe that this warning is a bug) at https://github.com/nodejs/node/blob/90dea9e3e003945f113aaca09c45f963fe566a47/lib/internal/modules/cjs/loader.js#L211C9-L211C17.

It looks like that code was touched a few months ago, but those changes had already been released in previous minor releases. However, we only see the the warning with Node.js 22.6.0 and not with 22.5.1.

Also, from that code it's not obvious to me how that label can be registered twice, because require() is sync and thus two require() calls to the same file cannot happen in parallel 🤔

Maybe this is caused by 01cf9bc, which added some conditions in startTimer/endTimer so maybe a label is created and then not cleaned up?

I can reproduce this locally! I will create a minimal reproduction.

@H4ad

Minimal reproduction

Put these files in a folder and run node index.js. It works with Node.js 22.5.1, but it warns with Node.js 22.6.0.

// index.js
const Module = require("module");
const requireDep2 = require("./dep1.js");

const globalCache = Module._cache;
Module._cache = Object.create(null);
require("./require-hook.js");
Module._cache = globalCache;

requireDep2();

// dep1.js
module.exports = function requireDep2() {
  require("./dep2.js");
};

// dep2.js

// (empty)

// require-hook.js
const Module = require("module");
const requireDep2 = require("./dep1.js");

const originalJSLoader = Module._extensions[".js"];
Module._extensions[".js"] = function customJSLoader(module, filename) {
  requireDep2();
  return originalJSLoader(module, filename);
};

This pattern of running the require hook with a "clean cache" is currently used by @babel/node and @babel/register (Babel's wrapper around the node CLI, and Babel's require hook) to make sure that if the user app shares some dependencies with Babel itself, those can still be compiled by the hook.

I would expect two things:

if the warning about re-using the same timer label recursively comes from Node.js internals it shouldn't be showed to the user
that timer shouldn't be installed at all, since I am not enabling any trace event

cc @H4ad, since you probably know what is going on here :)

Btw, Babel was added to CITGM a few weeks ago (nodejs/citgm#628) and it should have caught this, however I don't see Babel in the CITGM run for Node.js 22.6.0. What happened here?

Btw, Babel was added to CITGM a few weeks ago (nodejs/citgm#628) and it should have caught this, however I don't see Babel in the CITGM run for Node.js 22.6.0. What happened here?

A change in behaviour in npm 10.8.2 (npm/cli#7704 (comment)) meant that the CITGM runs for Node.js 22 (and main) are installing an outdated version of CITGM (before Babel was added).

$ node index.js
(node:269433) Warning: Label '[/XYZ/dep1.js] [./dep2.js]' already exists for debuglog.time
(Use `node --trace-warnings ...` to show where the warning was created)

I opened a PR to fix it, thanks for the report ❤️

Update test/fixtures/nodejsGH-54265/dep1.js

Update test/fixtures/nodejsGH-54265/dep2.js

Update test/fixtures/nodejsGH-54265/index.js

Update test/fixtures/nodejsGH-54265/require-hook.js

Navigation Menu

Repository navigation

Unactionable "Label ... already exists for `debuglog.time`" warning since Node.js 22.6 #54265

Version

Platform

Subsystem

What steps will reproduce the bug?

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

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

What do you see instead?

Additional information

Minimal reproduction

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Unactionable "Label ... already exists for debuglog.time" warning since Node.js 22.6 #54265

Description

Version

Platform

Subsystem

What steps will reproduce the bug?

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

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

What do you see instead?

Additional information

Activity

nicolo-ribaudo commented on Aug 8, 2024

nicolo-ribaudo commented on Aug 8, 2024

nicolo-ribaudo commented on Aug 8, 2024

Minimal reproduction

richardlau commented on Aug 8, 2024

avivkeller commented on Aug 8, 2024

H4ad commented on Aug 8, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

Unactionable "Label ... already exists for `debuglog.time`" warning since Node.js 22.6 #54265