feat(sdk): stream logs in wing test

apps/wing/src/cli.ts

@@ -205,6 +205,7 @@ async function main() {
       "Run tests that match the provided regex pattern within the selected entrypoint files"
     )
     .option("--no-clean", "Keep build output")
+    .option("--no-stream", "Do not stream logs")
     .option(
       "-o, --output-file <outputFile>",
       "File name to write test results to (file extension is required, supports only .json at the moment)"

apps/wing/src/commands/spinner-stream.ts

@@ -0,0 +1,55 @@
+import { WriteStream } from "tty";
+import ora from "ora";
+
+/**
+ * A stream that can write logs and print a spinner to the terminal without
+ * interfering with each other.
+ */
+export class SpinnerStream {
+  private stream: WriteStream;
+  private spinner: ora.Ora;
+  private buffer: string[] = [];
+  private interval: NodeJS.Timeout;
+
+  constructor(stream: WriteStream, text: string) {
+    this.stream = stream;
+    this.spinner = ora({ stream: this.stream, text, isEnabled: false });
+    this.interval = setInterval(() => {
+      this.updateSpinner();
+    }, 80);
+  }
+
+  public write(log: string): void {
+    this.buffer.push(log);
+  }
+
+  private updateSpinner(): void {
+    // Clear the spinner
+    this.stream.cursorTo(0);
+    this.stream.clearLine(1);
+
+    // Print any logs
+    for (const log of this.buffer) {
+      this.stream.write(log);
+    }
+    this.buffer = [];
+
+    // Redraw spinner
+    this.spinner.render();
+  }
+
+  public stopSpinner(): void {
+    // Stop looping
+    clearInterval(this.interval);
+
+    // Clear the spinner
+    this.stream.cursorTo(0);
+    this.stream.clearLine(1);
+
+    // Print any remaining logs
+    for (const log of this.buffer) {
+      this.stream.write(log);
+    }
+    this.buffer = [];
+  }
+}

apps/wing/src/commands/test/results.ts

@@ -28,14 +28,14 @@ export function printResults(testResults: SingleTestResult[], duration: number)
     (acc, { results }) => acc + results.filter(({ pass }) => !!pass).length,
     0
   );
-  console.log(" "); // for getting a new line- \n does't seem to work :(
   const areErrors = failing.length + unsupportedFiles.length > 0 && totalSum > 1;
   const showTitle = totalSum > 1;
 
   const res = [];
 
   if (showTitle) {
     // prints a list of the tests names with an icon
+    res.push("");
     res.push(`Results:`);
     res.push(...passing.map(({ testName }) => `    ${chalk.green("✓")} ${testName}`));
     res.push(...failing.map(({ testName }) => `    ${chalk.red("×")} ${testName}`));
@@ -44,7 +44,7 @@ export function printResults(testResults: SingleTestResult[], duration: number)
 
   if (areErrors) {
     // prints error messages form failed tests
-    res.push(" ");
+    res.push("");
     res.push("Errors:");
     res.push(
       ...[...failing, ...unsupportedFiles].map(({ testName, results }) =>
@@ -61,7 +61,7 @@ export function printResults(testResults: SingleTestResult[], duration: number)
   }
 
   // prints a summary of how many tests passed and failed
-  res.push(" ");
+  res.push("");
   const testCount = [
     failingTestsNumber && chalk.red(` ${failingTestsNumber} failed`),
     passingTestsNumber && chalk.green(` ${passingTestsNumber} passed`),
@@ -99,7 +99,7 @@ export function printResults(testResults: SingleTestResult[], duration: number)
     ).toFixed(2)}s`
   );
 
-  console.log(res.filter((value) => !!value).join("\n"));
+  console.log(res.join("\n"));
 }
 
 export interface TestResultsJson {

apps/wing/src/commands/test/test.ts

@@ -17,6 +17,7 @@ import { SNAPSHOT_ERROR_PREFIX } from "./snapshots-help";
 import { renderTestName } from "./util";
 import { withSpinner } from "../../util";
 import { compile, CompileOptions } from "../compile";
+import { SpinnerStream } from "../spinner-stream";
 
 const log = debug("wing:test");
 
@@ -43,6 +44,10 @@ export interface TestOptions extends CompileOptions {
    * How many times failed tests should be retried.
    */
   readonly retry?: number;
+  /**
+   * Whether to stream the logs of the test run.
+   */
+  readonly stream?: boolean;
 
   /**
    * Determine snapshot behavior.
@@ -220,7 +225,8 @@ async function executeTest(
  */
 export async function renderTestReport(
   entrypoint: string,
-  results: std.TestResult[]
+  results: std.TestResult[],
+  includeLogs: boolean = true
 ): Promise<string> {
   const out = new Array<string>();
 
@@ -245,14 +251,15 @@ export async function renderTestReport(
 
     const details = new Array<string>();
 
-    // add any log messages that were emitted during the test
-    for (const trace of result.traces) {
-      // only show detailed traces if we are in debug mode
-      if (trace.type === TraceType.RESOURCE && process.env.DEBUG) {
-        details.push(chalk.gray("[trace] " + trace.data.message));
-      }
-      if (trace.type === TraceType.LOG) {
-        details.push(chalk.gray(trace.data.message));
+    if (includeLogs) {
+      for (const trace of result.traces) {
+        // only show detailed traces if we are in debug mode
+        if (trace.type === TraceType.RESOURCE && process.env.DEBUG) {
+          details.push(chalk.gray("[trace] " + trace.data.message));
+        }
+        if (trace.type === TraceType.LOG) {
+          details.push(chalk.gray(trace.data.message));
+        }
       }
     }
 
@@ -357,9 +364,98 @@ async function runTestsWithRetry(
   return results;
 }
 
+function inferSeverityOfEvent(trace: std.Trace): "error" | "warn" | "info" | "debug" | "verbose" {
+  if (trace.data.status === "failure") {
+    return "error";
+  }
+  if (trace.type === TraceType.LOG) {
+    return "info";
+  }
+  if (trace.type === TraceType.RESOURCE) {
+    return "debug";
+  }
+  if (trace.type === TraceType.SIMULATOR) {
+    return "verbose";
+  }
+  return "verbose";
+}
+
+const SEVERITY_STRING = {
+  error: "ERROR  ",
+  warn: "WARNING",
+  info: "INFO   ",
+  debug: "DEBUG  ",
+  verbose: "VERBOSE",
+};
+
+const LOG_STREAM_COLORS = {
+  error: chalk.red,
+  warn: chalk.yellow,
+  info: chalk.green,
+  debug: chalk.blue,
+  verbose: chalk.gray,
+};
+
 async function testSimulator(synthDir: string, options: TestOptions) {
   const s = new simulator.Simulator({ simfile: synthDir });
   const { clean, testFilter, retry } = options;
+
+  let outputStream: SpinnerStream | undefined;
+  if (options.stream) {
+    outputStream = new SpinnerStream(process.stdout, "Running tests...");
+
+    const testMappings = extractTestMappings(s.listResources());
+
+    s.onTrace({
+      callback: (event) => {
+        // Filter out simulator and resource events if DEBUG isn't set
+        if (
+          (event.type === TraceType.SIMULATOR || event.type === TraceType.RESOURCE) &&
+          !process.env.DEBUG
+        ) {
+          return;
+        }
+
+        // Filter out simulator events if DEBUG=verbose isn't set
+        if (event.type === TraceType.SIMULATOR && process.env.DEBUG !== "verbose") {
+          return;
+        }
+
+        const env = extractTestEnvFromPath(event.sourcePath);
+        if (env === undefined) {
+          // This event is not associated with any test environment, so skip it.
+          return;
+        }
+        const testName = testMappings[env];
+        if (testName === undefined) {
+          // This event is not associated with any test environment, so skip it.
+          return;
+        }
+        if (testFilter && !testName.includes(testFilter)) {
+          // This test does not match the filter, so skip it.
+          return;
+        }
+
+        const pathSuffix = event.sourcePath.split("/").slice(2).join("/");
+        const severity = inferSeverityOfEvent(event);
+        const date = new Date(event.timestamp);
+        const hours = date.getHours().toString().padStart(2, "0");
+        const minutes = date.getMinutes().toString().padStart(2, "0");
+        const seconds = date.getSeconds().toString().padStart(2, "0");
+        const milliseconds = date.getMilliseconds().toString().padStart(3, "0");
+        const timestamp = `${hours}:${minutes}:${seconds}.${milliseconds}`;
+        let msg = "";
+        msg += chalk.gray(`[${timestamp}]`);
+        msg += LOG_STREAM_COLORS[severity](` [${SEVERITY_STRING[severity]}]`);
+        msg += chalk.white(` "${testName}" » /${pathSuffix}`);
+        msg += "\n";
+        msg += chalk.whiteBright(`${event.data.message}`);
+        msg += "\n";
+        outputStream!.write(msg);
+      },
+    });
+  }
+
   await s.start();
 
   const testRunner = s.getResource("root/cloud.TestRunner") as std.ITestRunnerClient;
@@ -370,7 +466,11 @@ async function testSimulator(synthDir: string, options: TestOptions) {
 
   await s.stop();
 
-  const testReport = await renderTestReport(synthDir, results);
+  if (options.stream) {
+    outputStream!.stopSpinner();
+  }
+
+  const testReport = await renderTestReport(synthDir, results, !options.stream);
   if (testReport.length > 0) {
     console.log(testReport);
   }
@@ -581,6 +681,62 @@ function sortTests(a: std.TestResult, b: std.TestResult) {
   return a.path.localeCompare(b.path);
 }
 
+/**
+ * Take a path like "root/env123/foo/bar" and return the environment number (123).
+ */
+function extractTestEnvFromPath(path: string): number | undefined {
+  const parts = path.split("/");
+  const envPart = parts[1];
+  if (!envPart.startsWith("env")) {
+    return undefined;
+  }
+  return parseInt(envPart.substring(3));
+}
+
+/*
+ * Take a path like "root/env123/foo/test:first test/bar" and return "first test".
+ */
+function extractTestNameFromPath(path: string): string | undefined {
+  const parts = path.split("/");
+  for (const part of parts) {
+    if (part.startsWith("test:")) {
+      return part.substring(5);
+    }
+  }
+  return undefined;
+}
+
+/*
+ * Take a list of paths like:
+ *
+ * root/env0/foo
+ * root/env0/test:first test        <-- this is a test
+ * root/env1/bar/test:second test   <-- this is a test
+ * root/env1/bar
+ *
+ * and extract the mapping from environment indices to test names:
+ *
+ * { 0: "first test", 1: "second test" }
+ */
+function extractTestMappings(paths: string[]): Record<number, string> {
+  const mappings: Record<number, string> = {};
+  for (const path of paths) {
+    const parts = path.split("/");
+    if (parts.some((p) => p.startsWith("test:"))) {
+      const env = extractTestEnvFromPath(path);
+      if (env === undefined) {
+        continue;
+      }
+      const testName = extractTestNameFromPath(path);
+      if (testName === undefined) {
+        continue;
+      }
+      mappings[env] = testName;
+    }
+  }
+  return mappings;
+}
+
 const MAX_BUFFER = 10 * 1024 * 1024;
 
 /**

examples/tests/sdk_tests/api/post.test.w

@@ -19,15 +19,15 @@ api.post("/path", inflight (req: cloud.ApiRequest): cloud.ApiResponse => {
 
 
 test "http.post and http.fetch can preform a call to an api" {
-    let url = api.url + "/path";
-    let response: http.Response = http.post(url, headers: { "content-type" => "application/json" }, body: Json.stringify(body));
-    let fetchResponse: http.Response = http.post(url, method: http.HttpMethod.POST, headers: { "content-type" => "application/json" }, body: Json.stringify(body));
+  let url = api.url + "/path";
+  let response: http.Response = http.post(url, headers: { "content-type" => "application/json" }, body: Json.stringify(body));
+  let fetchResponse: http.Response = http.post(url, method: http.HttpMethod.POST, headers: { "content-type" => "application/json" }, body: Json.stringify(body));
 
-    assert(response.body == Json.stringify(body));
-    assert(response.status == 200);
-    assert(response.url == url);
+  assert(response.body == Json.stringify(body));
+  assert(response.status == 200);
+  assert(response.url == url);
 
-    assert(fetchResponse.body == Json.stringify(body));
-    assert(fetchResponse.status == 200);
-    assert(fetchResponse.url == url);
-}
+  assert(fetchResponse.body == Json.stringify(body));
+  assert(fetchResponse.status == 200);
+  assert(fetchResponse.url == url);
+}

libs/wingsdk/src/std/resource.ts

@@ -198,12 +198,6 @@ export abstract class Resource extends Construct implements IResource {
    * actually bound.
    */
   public onLift(host: IInflightHost, ops: string[]): void {
-    log(
-      `onLift called on a resource (${this.node.path}) with a host (${
-        host.node.path
-      }) and ops: ${JSON.stringify(ops)}`
-    );
-
     for (const op of ops) {
       // Add connection metadata
       Node.of(this).addConnection({