Fix service behavior after dependency failure in watch mode (#596)

Previously, if a failure occurred in a persistent (i.e. top-level) service's dependencies, and if we were in watch mode on the 2nd or later iteration, then we completely forgot about the previously running service.

This had two similar effects, both of which could manifest as e.g. "port not available" errors:

- If the dependency was eventually fixed, we would try to start the service again, even though the previous version was still running.

- If the user exited wireit with Ctrl-C, we would not shut down the child process because we lost track of it.

This PR fixes these problems by transitioning to a new "started-broken" state when a failure in an already-running service's dependency occurs, which keeps a reference to the child process.

This PR also fixes some failure logging issues, where we would sometimes log the same failure multiple times, or sometimes log a failure at the very end of execution instead of as soon as it actually happens.

Fixes #568
Fixes #540

cc @SanderElias @deebloo @justinfagnani If you'd like to test out this fix early, I've published a pre-release as `wireit@0.9.2-pre.1`. If you try it, let me know how it goes!

CHANGELOG.md

@@ -6,7 +6,15 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and this project adheres to [Semantic
 Versioning](https://semver.org/spec/v2.0.0.html).
 
-<!-- ## [Unreleased] -->
+## [Unreleased]
+
+### Fixed
+
+- Fixed bug relating to services not getting shut down following an error in one
+  of its dependencies.
+- Fixed some cases of errors being logged multiple times.
+- Errors are now consistently logged immediately when they occur, instead of
+  sometimes only at the end of all execution.
 
 ## [0.9.1] - 2022-12-06
 

src/cli.ts

@@ -112,12 +112,6 @@ const run = async (): Promise<Result<void, Failure[]>> => {
           errors.push(result.error);
         }
       }
-      if (errors.length > 0) {
-        return {
-          ok: false,
-          error: errors,
-        };
-      }
     }
     return errors.length === 0
       ? {ok: true, value: undefined}

src/event.ts

@@ -100,6 +100,7 @@ export type Failure =
 interface ErrorBase<T extends PackageReference = ScriptReference>
   extends EventBase<T> {
   type: 'failure';
+  logged?: true;
 }
 
 /**

src/execution/standard.ts

@@ -387,6 +387,7 @@ export class StandardScriptExecution extends BaseExecutionWithCommand<StandardSc
           });
         }
       } else {
+        this._logger.log(result.error);
         // This failure will propagate to the Executor eventually anyway, but
         // asynchronously.
         //

src/logging/default-logger.ts

@@ -108,6 +108,10 @@ export class DefaultLogger implements Logger {
       }
 
       case 'failure': {
+        if (event.logged) {
+          return;
+        }
+        event.logged = true;
         const reason = event.reason;
         switch (reason) {
           default: {

src/test/service.test.ts

@@ -1275,4 +1275,102 @@ test(
   })
 );
 
+test(
+  'service watch mode recovery from dependency failure',
+  // service
+  //    |
+  //    v
+  // standard
+  timeout(async ({rig}) => {
+    const service = await rig.newCommand();
+    const standard = await rig.newCommand();
+    await rig.writeAtomic({
+      'package.json': {
+        scripts: {
+          service: 'wireit',
+          standard: 'wireit',
+        },
+        wireit: {
+          service: {
+            command: service.command,
+            service: true,
+            dependencies: ['standard'],
+          },
+          standard: {
+            command: standard.command,
+            files: ['input'],
+          },
+        },
+      },
+    });
+
+    await rig.write('input', '1');
+    const wireit = rig.exec('npm run service --watch');
+
+    // Initial build is OK.
+    await wireit.waitForLog(/\[standard\] Running/);
+    (await standard.nextInvocation()).exit(0);
+    await wireit.waitForLog(/\[standard\] Executed successfully/);
+    await service.nextInvocation();
+    await wireit.waitForLog(/\[service\] Service started/);
+    await wireit.waitForLog(/\[service\] Watching for file changes/);
+    await new Promise((resolve) => setTimeout(resolve, 50));
+    assert.equal(service.numInvocations, 1);
+    assert.equal(standard.numInvocations, 1);
+
+    // Introduce an error. Service keeps running but goes into a temporary
+    // "started-broken" state, where it awaits its dependencies being fixed.
+    await rig.write('input', '2');
+    await wireit.waitForLog(/\[standard\] Running/);
+    (await standard.nextInvocation()).exit(1);
+    await wireit.waitForLog(/\[standard\] Failed with exit status 1/);
+    await wireit.waitForLog(/\[service\] Watching for file changes/);
+    await new Promise((resolve) => setTimeout(resolve, 50));
+    assert.equal(service.numInvocations, 1);
+    assert.equal(standard.numInvocations, 2);
+
+    // Fix the error. Service restarts because the fingerprint of its dependency
+    // has changed.
+    await rig.write('input', '3');
+    await wireit.waitForLog(/\[standard\] Running/);
+    (await standard.nextInvocation()).exit(0);
+    await wireit.waitForLog(/\[standard\] Executed successfully/);
+    await service.nextInvocation();
+    await wireit.waitForLog(/\[service\] Service stopped/);
+    await wireit.waitForLog(/\[service\] Service started/);
+    await wireit.waitForLog(/\[service\] Watching for file changes/);
+    await new Promise((resolve) => setTimeout(resolve, 50));
+    assert.equal(service.numInvocations, 2);
+    assert.equal(standard.numInvocations, 3);
+
+    // Introduce another error. Again the service keeps running as
+    // "started-broken".
+    await rig.write('input', '4');
+    await wireit.waitForLog(/\[standard\] Running/);
+    (await standard.nextInvocation()).exit(1);
+    await wireit.waitForLog(/\[standard\] Failed with exit status 1/);
+    await wireit.waitForLog(/\[service\] Watching for file changes/);
+    await new Promise((resolve) => setTimeout(resolve, 50));
+    assert.equal(service.numInvocations, 2);
+    assert.equal(standard.numInvocations, 4);
+
+    // Fix the error, this time by reverting. This time the service doesn't
+    // restart, because the fingerprint has been restored to what it was before
+    // the failure.
+    await rig.write('input', '3');
+    await wireit.waitForLog(/\[standard\] Running/);
+    (await standard.nextInvocation()).exit(0);
+    await wireit.waitForLog(/\[standard\] Executed successfully/);
+    await wireit.waitForLog(/\[service\] Watching for file changes/);
+    await new Promise((resolve) => setTimeout(resolve, 50));
+    assert.equal(service.numInvocations, 2);
+    assert.equal(standard.numInvocations, 5);
+
+    wireit.kill();
+    await wireit.exit;
+    assert.equal(service.numInvocations, 2);
+    assert.equal(standard.numInvocations, 5);
+  })
+);
+
 test.run();