Fix out-of-order subcase logs (#4396)

- First commit fixes a bug where we were capturing a variable too late which prevented the subcase logs from actually being re-sorted the way they were supposed to be
- Second commit simplifies the code a bunch and moves the prefix to the beginning of the log line

Author: kainino0x

src/common/internal/logging/test_case_recorder.ts

@@ -181,4 +181,43 @@ export class TestCaseRecorder {
 
     this.logs.push(logMessage);
   }
+
+  /**
+   * Make a recorder that will defer all calls until `deferUntilPromise` resolves.
+   * This is used for running subcases, which run concurrently, to ensure that
+   * logs from all the previous subcases have been flushed before flushing new logs,
+   * so all logs are in order as if the subcases had not been concurrent.
+   */
+  makeDeferredSubRecorder(prefix: string, deferUntilPromise: Promise<void>) {
+    return new Proxy(this, {
+      get: (target, k) => {
+        switch (k) {
+          case 'logImpl':
+            return function (level: LogSeverity, name: string, baseException: unknown) {
+              globalTestConfig.testHeartbeatCallback();
+              void deferUntilPromise.then(() => {
+                target.logImpl(level, prefix + name, baseException);
+              });
+            };
+          case 'beginSubCase':
+            return function () {
+              globalTestConfig.testHeartbeatCallback();
+              void deferUntilPromise.then(() => {
+                target.beginSubCase();
+              });
+            };
+          case 'endSubCase':
+            return function (expectedStatus: Expectation) {
+              globalTestConfig.testHeartbeatCallback();
+              void deferUntilPromise.then(() => {
+                target.endSubCase(expectedStatus);
+              });
+            };
+          default:
+            /* eslint-disable-next-line @typescript-eslint/no-explicit-any */
+            return (target as any)[k];
+        }
+      },
+    });
+  }
 }

src/common/internal/test_group.ts

@@ -615,46 +615,11 @@ class RunCaseSpecific implements RunCase {
           };
 
           for (const subParams of this.subcases) {
-            // Make a recorder that will defer all calls until `allPreviousSubcasesFinalizedPromise`
-            // resolves. Waiting on `allPreviousSubcasesFinalizedPromise` ensures that
-            // logs from all the previous subcases have been flushed before flushing new logs.
-            const subcasePrefix = 'subcase: ' + stringifyPublicParams(subParams);
-            const subRec = new Proxy(rec, {
-              get: (target, k: keyof TestCaseRecorder) => {
-                const prop = rec[k] ?? TestCaseRecorder.prototype[k];
-                if (typeof prop === 'function') {
-                  testHeartbeatCallback();
-                  return function (...args: Parameters<typeof prop>) {
-                    void allPreviousSubcasesFinalizedPromise.then(() => {
-                      // Prepend the subcase name to all error messages.
-                      for (const arg of args) {
-                        if (arg instanceof Error) {
-                          try {
-                            arg.message = subcasePrefix + '\n' + arg.message;
-                          } catch {
-                            // If that fails (e.g. on DOMException), try to put it in the stack:
-                            let stack = subcasePrefix;
-                            if (arg.stack) stack += '\n' + arg.stack;
-                            try {
-                              arg.stack = stack;
-                            } catch {
-                              // If that fails too, just silence it.
-                            }
-                          }
-                        }
-                      }
-
-                      // eslint-disable-next-line @typescript-eslint/no-explicit-any
-                      const rv = (prop as any).apply(target, args);
-                      // Because this proxy executes functions in a deferred manner,
-                      // it should never be used for functions that need to return a value.
-                      assert(rv === undefined);
-                    });
-                  };
-                }
-                return prop;
-              },
-            });
+            // Defer subcase logs so that they appear in the correct order.
+            const subRec = rec.makeDeferredSubRecorder(
+              `(in subcase: ${stringifyPublicParams(subParams)}) `,
+              allPreviousSubcasesFinalizedPromise
+            );
 
             const params = mergeParams(this.params, subParams);
             const subcaseQuery = new TestQuerySingleCase(
@@ -684,16 +649,16 @@ class RunCaseSpecific implements RunCase {
               getExpectedStatus(subcaseQuery)
             )
               .then(() => {
-                subRec.info(new Error('OK'));
+                subRec.info(new Error('subcase ran'));
               })
               .catch(ex => {
                 if (ex instanceof SkipTestCase) {
-                  // Convert SkipTestCase to info messages
+                  // Convert SkipTestCase to an info message so it won't skip the whole test
                   ex.message = 'subcase skipped: ' + ex.message;
-                  subRec.info(ex);
+                  subRec.info(new Error('subcase skipped'));
                   ++skipCount;
                 } else {
-                  // Since we are catching all error inside runTest(), this should never happen
+                  // We are catching all other errors inside runTest(), so this should never happen
                   subRec.threw(ex);
                 }
               })

src/demo/subcases.spec.ts

@@ -5,19 +5,28 @@ import { UnitTest } from '../unittests/unit_test.js';
 
 export const g = makeTestGroup(UnitTest);
 
-g.test('pass_warn_fail')
+g.test('skip')
+  .paramsSubcasesOnly(u => u.combine('y', [1, 2]))
+  .fn(t => {
+    t.skip('I skip!');
+  });
+
+g.test('pass_warn_fail_skip')
   .params(u =>
     u
-      .combine('x', [1, 2, 3]) //
+      .combine('x', [0, 1, 2, 3]) //
       .beginSubcases()
       .combine('y', [1, 2, 3])
   )
   .fn(t => {
     const { x, y } = t.params;
-    if (x + y > 5) {
-      t.fail();
-    } else if (x + y > 4) {
-      t.warn();
+    if (x + y >= 5) {
+      t.fail('I fail!');
+    } else if (x + y >= 4) {
+      t.warn('I warn!');
+    }
+    if (x + y === 1 || x + y === 6) {
+      t.skip('I skip!');
     }
   });
 

src/resources/cache/hashes.json

@@ -343,7 +343,7 @@ g.test('subcases,skip')
     const expectedStatus = allSkip ? 'skip' : 'pass';
     t0.expect(
       values[0].status === expectedStatus,
-      `expect: ${values[0].status} === ${expectedStatus}}, allSkip: ${allSkip}`
+      `expect: ${values[0].status} === ${expectedStatus}, allSkip: ${allSkip}`
     );
   });