watch: preserve output when gracefully restarted

[theoludwig]

#45717 added --watch-preserve-output:

Disable the clearing of the console when watch mode restarts the process.

However, when the process is "gracefully restarting" (if the process takes more than 500ms to stop), it is still clearing the console which is unexpected with --watch-preserve-output.

This PR fixes this bug.

[theoludwig]

I tried investigating https://github.com/nodejs/node/blob/main/test/sequential/test-watch-mode.mjs to add a test case, but not sure how to proceed, help would be appreciated, thanks!
Hopefully, the test case is not blocking for merging this PR, as far as I can tell this existing code path is not covered by tests yet anyway.

Might need to add an option to the runWriteSucceed function to "bypass" this condition:

node/test/sequential/test-watch-mode.mjs

Lines 118 to 120 in 56ff307

	if (!data.startsWith('Waiting for graceful termination') && !data.startsWith('Gracefully restarted')) {
	stdout.push(data);
	}

Is this condition needed to avoid flaky tests?
The condition could look something like:

if (
  shouldIncludeGracefulRestartLog ||
  (!data.startsWith('Waiting for graceful termination') && !data.startsWith('Gracefully restarted'))
) {
  stdout.push(data);
}

The test might look something like:

it('should preserve output when --watch-preserve-output flag is passed and process is gracefully restarting', async () => {
  const file = createTmpFile("console.log('running'); setTimeout(() => {}, 600);");
  const args = ['--watch-preserve-output', file];
  const { stderr, stdout,  } = await runWriteSucceed({ file, watchedFile: file, args, shouldIncludeGracefulRestartLog: true });

  assert.strictEqual(stderr, '');
  assert.deepStrictEqual(stdout, [
    'running',
    `Completed running ${inspect(file)}`,
    `Restarting ${inspect(file)}`,
    `Waiting for graceful termination of ${inspect(file)}`,
    `Gracefully restarted ${inspect(file)}`,
    'running',
    `Completed running ${inspect(file)}`,
  ]);
});

But I don't know how to "simulate" a slow (500ms) graceful exit, this is not working: console.log('running'); setTimeout(() => {}, 600);.

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 87.09%. Comparing base (66c8076) to head (90a6ecf).
Report is 559 commits behind head on main.

Additional details and impacted files

@@            Coverage Diff             @@
##             main   #54323      +/-   ##
==========================================
- Coverage   87.09%   87.09%   -0.01%     
==========================================
  Files         647      647              
  Lines      181843   181843              
  Branches    34894    34887       -7     
==========================================
- Hits       158383   158371      -12     
- Misses      16766    16771       +5     
- Partials     6694     6701       +7     

see 29 files with indirect coverage changes

[jakecastelli]

do you have a minimal repro example to demonstrate that the log will be cleared? I was not able to reproduce it.

[theoludwig]

do you have a minimal repro example to demonstrate that the log will be cleared? I was not able to reproduce it.

I don't have a minimal repro, but I found out this bug while developing in a monorepo with lot of dependencies, fortunately the application is open source (not on GitHub yet), you can try to reproduce, with the following commands:

# Clone the repo (and go to the correct branch)
git clone ssh://git@git.theoludwig.fr:1234/theoludwig/wikipedia-game-solver.git
git checkout develop-next

# Go to the project root
cd wikipedia-game-solver

# Configure environment variables
cp .env.example .env
cp apps/website/.env.example apps/website/.env
cp apps/api/.env.example apps/api/.env

# Install dependencies
pnpm install --frozen-lockfile

# Start the api
cd apps/api
node --run dev

Then you can try to modify this file: apps/api/src/app/routes/get.ts:

import router from "@adonisjs/core/services/router"

router.get("/", async () => {
  return {
    hello: "world",
  }
})

Doing so, log "Gracefully restarted './src/bin/server.ts'", and clear the console, even with --watch-preserve-output.

---

The bug basically occurs when the Node.js app takes more than 500ms to exit. As you can see in the diff, the function in Node.js look like this:

function reportGracefulTermination() {
  // Log if process takes more than 500ms to stop.
  let reported = false;
  clearTimeout(graceTimer);
  graceTimer = setTimeout(() => {
    reported = true;
    process.stdout.write(`${blue}Waiting for graceful termination...${white}\n`);
  }, 500).unref();
  return () => {
    clearTimeout(graceTimer);
    if (reported) {
      // PROBLEMATIC line:
      process.stdout.write(`${clear}${green}Gracefully restarted ${kCommandStr}${white}\n`);
    }
  };
}

For the test, it would be nice to create a minimal repro, but as said:

• I don't know how to "simulate" a slow (500ms) graceful exit.
• reportGracefulTermination function is not covered by tests yet, so I don't know how to proceed.

[theoludwig]

cc @MoLow
Maybe you know better this part of the code? 😄

[jakecastelli]

Ok, thanks for providing more information. Now I have a small repro here:

import http from "node:http";

const host = "localhost";
const port = 8000;

const server = http.createServer();
server.listen(port, host, () => {
  console.log(`Server is running on http://${host}:${port}`);

  setTimeout(() => {
    process.kill(process.pid);
    console.log("killing the process");
  }, 1000);
});

process.on("SIGTERM", () => {
  console.log("Received SIGTERM, shutting down gracefully...");
  setTimeout(() => {
    process.exit(0);
  }, 10000);
});

When you see killing the process you need to quickly press save once in order to trigger the reload and then it can reproduce.

[theoludwig]

Thank you for taking the time to make a small reproduction example, I tried, and indeed the bug shows in this small example.

Might use this small repro to make a test.

[MoLow]

I am on vacation without a computer until mid-september, I will give a look when I am back if no one else does before me

[MoLow]

Implementation LGTM, please add a test similar to the one added in #45717

[theoludwig]

Implementation LGTM, please add a test similar to the one added in #45717

@MoLow Thank you for coming back to this PR.
Tests, that's where, I would need help. 😅

When I opened this PR, I already tried to add a test in test/sequential/test-watch-mode.mjs, but couldn't make it work, as explained in #54323 (comment).

Could you please explain a little bit more, the reasoning behind this condition: (!data.startsWith('Waiting for graceful termination') && !data.startsWith('Gracefully restarted')) in runWriteSucceed? Is it to avoid flaky tests?

The code being edited by this PR is not already covered by tests on main, so is it blocking for merging and fixing the bug? Of course, it would be better with a test, but that could be done in a follow up PR, right? Especially because the changes are "trivial" and not yet covered by tests anyway.

I still tried again, and I've done that:

it('should preserve output when --watch-preserve-output flag is passed and process is gracefully restarting', async () => {
  const file = createTmpFile(`
  import http from "node:http";

  const host = "0.0.0.0";
  const port = 8_000;

  const server = http.createServer();
  server.listen(port, host, () => {
    console.log(\`Server is running on http://\${host}:\${port}\`);

    setTimeout(() => {
      process.kill(process.pid);
      console.log("killing the process");
    }, 1_000);
  });

  process.on("SIGTERM", () => {
    console.log("Received SIGTERM, shutting down gracefully...");
    setTimeout(() => {
      process.exit(0);
    }, 5_000);
  });
  `);
  const args = ['--watch-preserve-output', file];
  const { stderr, stdout,  } = await runWriteSucceed({ file, watchedFile: file, args, shouldIncludeGracefulRestartLog: true });
  assert.strictEqual(stderr, '');
  assert.deepStrictEqual(stdout, [
    'running',
    `Completed running ${inspect(file)}`,
    `Restarting ${inspect(file)}`,
    `Waiting for graceful termination of ${inspect(file)}`,
    `Gracefully restarted ${inspect(file)}`,
    'running',
    `Completed running ${inspect(file)}`,
  ]);
});
});

I've basically took the minimal reproduction example from @jakecastelli, and tried making a test with it. But executing ./node test/sequential/test-watch-mode.mjs, result in test did not finish before its parent and was cancelled.

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/62849/

[theoludwig]

These are unrelated test failures, right?

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/62858/

[jakecastelli]

Yes, looks unrelated, I have kicked started a rerun

[nodejs-github-bot]

Landed in 89a2f56