Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug]: FORCE_COLOR set internally leaks through to tests on Windows after upgrade to Node.js v18.17.0 #14391

Closed
aweebit opened this issue Aug 7, 2023 · 17 comments

Comments

@aweebit
Copy link

aweebit commented Aug 7, 2023

Version

29.6.2

Steps to reproduce

  1. Install Node.js v18.17.0 on Windows.
  2. Run the following commands in Git Bash:
mkdir jest-force-color
cd jest-force-color
npm install -D jest
echo 'test("color", () => expect(process.env.FORCE_COLOR).toBeUndefined());' > first.test.js
cp first.test.js second.test.js
  1. Open either Git Bash, cmd or PowerShell.
  2. Make sure the FORCE_COLOR environment variable is unset.
  3. Run the following command:
npx jest --no-cache

Expected behavior

I expect the tests to pass.

Actual behavior

Instead, both of them fail because the value of process.env.FORCE_COLOR is '1'.

Additional context

The issue is not present when using Node.js versions prior to v18.17.0. I believe the fact it appears after the upgrade is due to nodejs/node#48034.

The upgrade broke tests in tj/commander.js checking the output of node child processes, and it was quite hard to figure out what the reason was.

Environment

System:
  OS: Windows 10 10.0.19045
  CPU: (8) x64 Intel(R) Core(TM) i7-8550U CPU @ 1.80GHz
Binaries:
  Node: 18.17.0 - C:\Program Files\nodejs\node.EXE
  Yarn: 1.22.19 - C:\Program Files (x86)\Yarn\bin\yarn.CMD
  npm: 9.8.1 - C:\Program Files\nodejs\npm.CMD
npmPackages:
  jest: ^29.6.2 => 29.6.2
@shadowspawn
Copy link

I was able to reproduce some unexpected test failures on Mac too, when I upgraded Node to v18.17.0.

A trigger might be tests running in parallel. The failures I was seeing went away when I tried npx jest --runInBand.

@mrazauskas
Copy link
Contributor

mrazauskas commented Aug 8, 2023

--runInBand is not using workers, so I guess the problem originates from these lines:

import {stdout as stdoutSupportsColor} from 'supports-color';

const forceColor = stdoutSupportsColor ? {FORCE_COLOR: '1'} : {};

const options: ForkOptions = {
cwd: process.cwd(),
env: {
...process.env,
JEST_WORKER_ID: String(this._options.workerId + 1), // 0-indexed workerId, 1-indexed JEST_WORKER_ID
...forceColor,
},
// Suppress --debug / --inspect flags while preserving others (like --harmony).
execArgv: process.execArgv.filter(v => !/^--(debug|inspect)/.test(v)),
// default to advanced serialization in order to match worker threads
serialization: 'advanced',
silent,
...this._options.forkOptions,
};
this._child = fork(this._childWorkerPath, [], options);

I had similar issue while testing a CLI tool. If I recall it right, all this is needed because of limitations of child process and chalk. argv is not passed to child processes, so this mechanism is here to pass the --colors flag to chalk. (Jest does not consume --colors internally.)

The problem I was facing: supports-color does not respect NO_COLOR environment variable, which is respected by Node.

At first I thought it would be enough to use worker threads (argv is not an issue in this case). This is why the workerThreads configuration option was added in #13939. Experimental! Use with caution.


Other part of issue was related with vscode-jest. See jest-community/vscode-jest#971. Mentioning it here because of tj/commander.js#1950 (comment).


In the end my solution was to use MYAPP_NO_COLOR environment variable. This always works. Not sure if that is helpful for you.

@mrazauskas
Copy link
Contributor

mrazauskas commented Aug 8, 2023

Probably it would be the best to remove --color and --colors flags and the logic around supports-color in the next major. This would allow keeping environment variables untouched.

EDIT More motivation: color support is about the environment and this piece of data must be known before the app starts. E.g., jest --no-colrs will throw validation error. Should the message use colors or not?

@aweebit
Copy link
Author

aweebit commented Aug 8, 2023

Probably it would be the best to remove --color and --colors flags and the logic around supports-color in the next major. This would allow keeping environment variables untouched.

From a quick look at just the ChildProcessWorker.ts file, it might be a better idea to move the logic around supports-color to the place where the worker is constructed and set JEST_FORCE_COLOR instead of FORCE_COLOR there, then use the value in the child process to decide whether to pass --colors to chalk.

@mrazauskas
Copy link
Contributor

The trick is that --colors is not passed anywhere and does not exist in Jest’s logic at all. chalk simply checks if --colors (or any numerous variation of it) is present in process.argv. It is using supports-color to do that, if I am not mistaken.

@aweebit
Copy link
Author

aweebit commented Aug 8, 2023

chalk.level could be used then.

This seems to work perfectly:

// program.js
console.log([ 123, 'abc', () => {} ]);
// child.mjs
import { execFile } from 'node:child_process';
import { promisify } from 'node:util';
const execFileAsync = promisify(execFile);

import { Chalk } from 'chalk';

const { JEST_CHALK_LEVEL } = process.env;
const chalk = new Chalk({ level: +JEST_CHALK_LEVEL });

console.log(chalk.blue('Hello world!'));
const { stdout } = await execFileAsync('node', ['program.js']);
console.log(stdout);
// parent.mjs
import { fork } from 'node:child_process';
import { supportsColor } from 'chalk';

const JEST_CHALK_LEVEL = supportsColor ? String(supportsColor.level) : '0';
const env = { ...process.env, JEST_CHALK_LEVEL };
fork('child.mjs', [], { env });

Tested with:

node parent.mjs # 'Hello world!' in color
FORCE_COLOR=1 node parent.mjs # everything in color
node parent.mjs --no-color # no color

@aweebit
Copy link
Author

aweebit commented Aug 8, 2023

Could even do

delete process.env.JEST_WORKER_ID;
delete process.env.JEST_CHALK_LEVEL;

after using the values to leave the environment untouched for tests and child processes spawned from them.

@github-actions
Copy link

github-actions bot commented Sep 7, 2023

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 30 days.

@github-actions github-actions bot added the Stale label Sep 7, 2023
@shadowspawn
Copy link

I'll expand a bit on the failing tests I am seeing in Commander. We do not use Chalk or any ascii text colouring in Commander or in the tests. However, stdout from executing a fixture in a child process contains the ascii escape sequence to turn the text green, which was presumably inherited somehow from Jest and/or node.

The failing test looks like

const execFileAsync = util.promisify(childProcess.execFile);

test('example failing test', async() => {
  const { stdout } = await execFileAsync('node', ['--inspect-port=9270', fixture, 'sub']);
  expect(stdout).toBe("[ '--inspect-port=127.0.0.1:9271' ]\n");
});

The fixture effectively does this:

childProcess.spawn('node', [ '--inspect-port=127.0.0.1:9271', 'sub.js'], { stdio: 'inherit' })

The final file is just:

console.log(process.execArgv);

I have not been able to reproduce the failure in a smaller setup, so I might be missing some critical step or parallel test to trigger the problem condition.

@aweebit
Copy link
Author

aweebit commented Sep 11, 2023

This is still relevant.

@github-actions
Copy link

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 30 days.

@github-actions github-actions bot added the Stale label Oct 11, 2023
@shadowspawn
Copy link

I worked around the colour issue in Commander by adding process.env.FORCE_COLOR = 0 to the fixtures being used in the tests that broke. That is low enough impact that if no one else is reporting problems then I won't comment next stale warning and let this issue close!

tj/commander.js#2011

@shadowspawn
Copy link

Possibly related: #12162

@github-actions github-actions bot removed the Stale label Oct 12, 2023
Copy link

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 30 days.

@github-actions github-actions bot added the Stale label Nov 11, 2023
Copy link

This issue was closed because it has been stalled for 30 days with no activity. Please open a new issue if the issue is still relevant, linking to this one.

@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Dec 11, 2023
Copy link

This issue was closed because it has been stalled for 30 days with no activity. Please open a new issue if the issue is still relevant, linking to this one.

Copy link

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.
Please note this issue tracker is not a help forum. We recommend using StackOverflow or our discord channel for questions.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Jan 11, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants