[heft] heft watch mode always logs the re-run requestor task as unknown

[bartvandenende-wm]

Summary

When using the heft watch mode using heft start a re-run triggered by a heft-plugin is not properly logged as requestor in the console.

Repro steps

1. cd 'rushstack/build-tests-samples/heft-webpack-basic-tutorial'
2. rush build --to .
3. rushx start
4. Make a file change in the src folder
5. Observe the console print ````New run requested by unknown task```

Expected result:
I would expect heft to print the name of the task operation that triggered to re-run, for example if the heft-typescript-plugin triggers runOptions.requestRun it should print something along the below lines:

New run requested by typescript

Actual result:

The operation task is always undefined

New run requested by undefined task

Details

Heft logs the message with the requestor here:

rushstack/apps/heft/src/cli/HeftActionRunner.ts

Line 345 in 2c8bed2

terminal.writeLine(Colors.bold(`New run requested by ${requestor || 'unknown task'}`));

which uses the Operation name value here:

rushstack/libraries/operation-graph/src/Operation.ts

Line 282 in 2c8bed2

return requestRun(this.name);

but the name value is never set for the operation when heft initialises it:

rushstack/apps/heft/src/cli/HeftActionRunner.ts

Line 474 in 2c8bed2

groupName: task.parentPhase.phaseName,

Adding the task name explicitly to the Operation initialisation in HeftActionRunner.ts solves this:

      groupName: task.parentPhase.phaseName,
      name: task.taskName,

Standard questions

Please answer these questions to help us investigate your issue more quickly:

Question	Answer
@rushstack/heft version?	0.63.5
Operating system?	Mac
Would you consider contributing a PR?	Yes
Node.js version (node -v)?	v18.16.1

[octogonz]

@bartvandenende-wm has proposed a simple fix in #4468

However I'd like to consider requiring a logging name for every operation, as illustrated in my alternate PR #4469

[octogonz]

Also, in testing this change, I noticed that the reported watcher seems a bit counterintuitive:

Using heft start in heft-web-rig-app-tutorial:

• Saving a change to start.tsx prints these logs:

  New run requested by typescript task  👈👈👈
  
  Starting incremental build...
   ---- build started ----
  [build:typescript] File change detected. Starting incremental compilation...
  [build:typescript] Found 0 errors. Watching for file changes.
  New run requested by sass task  👈👈👈
  Cancelling incremental build...
  -------------------- Aborted (0.213s) --------------------
  
  Starting incremental build...
   ---- build started ----
  [build:webpack] Running incremental Webpack compilation
   ---- build finished (0.071s) ---- 
  -------------------- Finished (0.073s) --------------------
  Waiting for changes. Press CTRL + C to exit...
  

• Saving a change to start.css prints these logs:

  New run requested by sass task  👈👈👈
  
  Starting incremental build...
   ---- build started ----
  [build:typescript] Copied 2 folders or files and linked 0 files
  [build:webpack] Running incremental Webpack compilation
   ---- build finished (0.064s) ---- 
  -------------------- Finished (0.066s) --------------------
  Waiting for changes. Press CTRL + C to exit...
  
  New run requested by webpack task  👈👈👈
  
  Starting incremental build...
   ---- build started ---- 
  [build:webpack] Running incremental Webpack compilation
   ---- build finished (0.056s) ---- 
  -------------------- Finished (0.072s) --------------------
  Waiting for changes. Press CTRL + C to exit...
  

To a casual observer, it seems counterintuitive that modifying *.tsx would trigger the sass task. If the underlying logic is working as expected, maybe the logging message could be rephrased to better capture what's going on?

@D4N14L @dmichon-msft

[dmichon-msft]

To a casual observer, it seems counterintuitive that modifying *.tsx would trigger the sass task. If the underlying logic is working as expected, maybe the logging message could be rephrased to better capture what's going on?

The run is triggered by the SASS task because Heft's file watcher support doesn't actually monitor the output of globs, it monitors all the file system calls made to evaluate them. This is something that could be changed, but at the time of implementation it was easier to provide a watching file system adapter.

TL;DR, the SASS task triggers a rerun because a folder that was readdir'd during the evaluation of the SASS glob had a change to its directory listing.

[bartvandenende-wm]

good callout @octogonz, does it mean we have 2 plugins (sass and typescript) that trigger from the same Heft's file watcher support event simultaneously causing the first abort run?

A suggestion for further improved (verbose) log traceability would be for the task plugin to provide a trigger reason on the requestRun callback.

[octogonz]

The run is triggered by the SASS task because Heft's file watcher support doesn't actually monitor the output of globs, it monitors all the file system calls made to evaluate them. This is something that could be changed, but at the time of implementation it was easier to provide a watching file system adapter.

I see, so Heft's watcher cannot see the globs themselves? And therefore it does not have enough information to determine whether the disk events actually affect the actual input files for SASS?

Then maybe the log message is correct, and we should instead focus on optimizing specific tasks such as sass.