Forward log messages from worker thread to main thread (#1176)

Proposed fix for #1120

Note that this fix has some downsides as well. So I'm not 100% sure we
should take it yet. Looking for opinions.

### Problem
- When workers (i.e. the compiler and debugger workers in VS Code) write
logs, these are not surfaced in the VS Code output window along with
other logs. This applies to logging from JavaScript (e.g `log.info()`
calls), logs from Rust (e.g. `info!()` macros), and Rust panics.

### Fix
- Workers, instead of logging directly to the console, now send a
message to the main thread. The main thread logs the message as normal
(to the Developer Tools console for playground/website, to the Output
window for VS Code). All logs are now visible in the VS Code output
window.

### Concerns about this fix
- Logging becomes a nontrivial code path, which may defeat the purpose
of using logging to debug tricky bugs.
- For log messages, the original callstack in the worker is lost.
Instead the callstack from the message handler in the main thread is
shown (see screenshots). This will *not* be a problem for panic
messages, which capture a stack trace explicitly. Personally, I wouldn't
expect to see callstacks in log messages anyway, it's just something
that Chrome does.
- Log messages now become part of the message traffic between the main
thread and the worker thread, which _could_ be a perf concern if noisy
logs start slowing down the "real" communication between the threads.
This is hypothetical; I haven't been able to find an actual scenario
where this is a problem. We can mitigate this by being careful we're not
writing super-noisy logs at the default log level ("info" and up).

### Alternate solution
- Do nothing! There's actually a way to access the console logs for the
worker thread in VS Code. You can bring up the Chrome developer tools
using the "Toggle Developer Tools" VS Code command. It's not as
convenient as having them in the output window, but they're there.

### Notes
- Once a worker is started, there's no way to set the log level for that
worker. This is a preexisting issue, and probably not a big deal in
practice, since most of the workers (compiler, debugger) are short-lived
and can just be run again with a different log level if we're trying to
repro a specific issue.
- A bonus fix here is increasing the stack trace frames to 20 (from 10)
when logging panics, since most of the stack trace tends to get taken up
by the logging code itself.

### Screenshots

These show an `error!` log and a `panic!` surfaced from the WASM module.

VS Code:

**Before, release build, VS Code**

<details>
<summary>Screenshot</summary>

![Screenshot 2024-02-18
150303](https://github.com/microsoft/qsharp/assets/16928427/ac918d85-4c8f-4076-b62a-c83b589217d5)

</details>

**After, release build, VS Code** 

<details>
<summary>Screenshot</summary>

![Screenshot 2024-02-18
145822](https://github.com/microsoft/qsharp/assets/16928427/975c541d-3fc0-4248-8bc5-a3b4b11c30c6)

</details>

**Before, debug build, VS Code**

<details>
<summary>Screenshot</summary>

![Screenshot 2024-02-18
150600](https://github.com/microsoft/qsharp/assets/16928427/0b2a89df-32a1-4e44-a1d2-dbe49d6e43ff)

</details>

**After, debug build, VS Code**

<details>
<summary>Screenshot</summary>

![Screenshot 2024-02-18
145544](https://github.com/microsoft/qsharp/assets/16928427/00161a8c-4a75-452c-ae23-eb490faa5a01)

</details>

**Before, release build, Developer Tools window in VS Code**

<details>
<summary>Screenshot</summary>


![image](https://github.com/microsoft/qsharp/assets/16928427/6f7d66e5-734c-4f9d-bb18-f4fd5bfb810e)

</details>

Playground - no real improvement here, since the worker logs were
already shown in the Developer Tools console:

**Before, release build, playground**

<details>
<summary>Screenshot</summary>

![Screenshot 2024-02-18
150200](https://github.com/microsoft/qsharp/assets/16928427/49b25013-a830-48b7-9670-f26660966725)

</details>

**After, release build, playground**

<details>
<summary>Screenshot</summary>

![Screenshot 2024-02-18
142645](https://github.com/microsoft/qsharp/assets/16928427/87b1867d-bd38-4745-b624-83a902e63582)

</details>

**Before, debug build, playground**

<details>
<summary>Screenshot</summary>

![Screenshot 2024-02-18
150503](https://github.com/microsoft/qsharp/assets/16928427/5d7fc6b9-7c1d-453f-9261-ddf6ddac4685)

![Screenshot 2024-02-18
150519](https://github.com/microsoft/qsharp/assets/16928427/4d4a2652-c151-44ca-8c7f-8cc1f86bc454)

</details>

**After, debug build, playground**

<details>
<summary>Screenshot</summary>

![Screenshot 2024-02-18
145153](https://github.com/microsoft/qsharp/assets/16928427/9cfea79c-6f71-47c3-94aa-19b137b3a9af)

</details>

npm/src/compiler/events.ts

@@ -2,15 +2,14 @@
 // Licensed under the MIT License.
 
 import { ShotResult, Dump, Result } from "./common.js";
-import { TelemetryEvent, log } from "../log.js";
+import { log } from "../log.js";
 import { IServiceEventTarget } from "../workers/common.js";
 
 // Create strongly typed compiler events
 export type QscEventData =
   | { type: "Message"; detail: string }
   | { type: "DumpMachine"; detail: { state: Dump; stateLatex: string } }
-  | { type: "Result"; detail: Result }
-  | { type: "telemetry-event"; detail: TelemetryEvent };
+  | { type: "Result"; detail: Result };
 
 export type QscEvents = Event & QscEventData;
 

npm/src/workers/common.ts

@@ -84,6 +84,17 @@ export interface IServiceEventMessage {
   detail: unknown;
 }
 
+/**
+ * Common event types all workers can send.
+ */
+type CommonEvent =
+  | { type: "telemetry-event"; detail: TelemetryEvent }
+  | {
+      type: "log";
+      detail: { level: number; target: string; data: any[] };
+    };
+type CommonEventMessage = CommonEvent & { messageType: "common-event" };
+
 /**
  * Strongly typed EventTarget interface. Used as a constraint for the
  * event target that "requestWithProgress" methods should take in the service.
@@ -211,18 +222,31 @@ export function createProxyInternal<
   }
 
   function onMsgFromWorker(
-    msg: ResponseMessage<TService> | EventMessage<TServiceEventMsg>,
+    msg:
+      | ResponseMessage<TService>
+      | EventMessage<TServiceEventMsg>
+      | CommonEventMessage,
   ) {
     if (log.getLogLevel() >= 4)
       log.debug("Proxy: Received message from worker: %s", JSON.stringify(msg));
 
-    if (msg.messageType === "event") {
-      // For telemetry events, just log and exit. There is nothing else waiting to consume them.
-      if (msg.type === "telemetry-event") {
-        const detail = msg.detail as TelemetryEvent;
-        log.logTelemetry(detail);
-        return;
+    if (msg.messageType === "common-event") {
+      const commonEvent = msg; // assignment is necessary here for TypeScript to narrow the type
+      switch (commonEvent.type) {
+        case "telemetry-event":
+          {
+            const detail = commonEvent.detail;
+            log.logTelemetry(detail);
+          }
+          break;
+        case "log":
+          {
+            const detail = commonEvent.detail;
+            log.logWithLevel(detail.level, detail.target, ...detail.data);
+          }
+          break;
       }
+    } else if (msg.messageType === "event") {
       const event = new Event(msg.type) as Event & TServiceEventMsg;
       event.detail = msg.detail;
 
@@ -250,7 +274,6 @@ export function createProxyInternal<
         curr = undefined;
         doNextRequest();
       }
-      return;
     }
   }
 
@@ -425,28 +448,61 @@ export function initService<
   TServiceEventMsg extends IServiceEventMessage,
 >(
   postMessage: (
-    msg: ResponseMessage<TService> | EventMessage<TServiceEventMsg>,
+    msg:
+      | ResponseMessage<TService>
+      | EventMessage<TServiceEventMsg>
+      | CommonEventMessage,
   ) => void,
   serviceProtocol: ServiceProtocol<TService, TServiceEventMsg>,
   wasm: Wasm,
   qscLogLevel?: number,
 ): (req: RequestMessage<TService>) => Promise<void> {
-  function telemetryHandler(telemetry: TelemetryEvent) {
+  function postTelemetryMessage(telemetry: TelemetryEvent) {
     postMessage({
-      messageType: "event",
+      messageType: "common-event",
       type: "telemetry-event",
       detail: telemetry,
     });
   }
 
+  function postLogMessage(level: number, target: string, ...args: any) {
+    if (log.getLogLevel() < level) {
+      return;
+    }
+
+    let data = args;
+    try {
+      // Only structured cloneable objects can be sent in worker messages.
+      // Test if this is the case.
+      structuredClone(args);
+    } catch (e) {
+      // Uncloneable object.
+      // Use String(args) instead of ${args} to handle all possible values
+      // without throwing. See: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/String#string_coercion
+      data = ["unsupported log data " + String(args)];
+    }
+    postMessage({
+      messageType: "common-event",
+      type: "log",
+      detail: { level, target, data },
+    });
+  }
+
+  // Override the global logger
+  log.error = (...args) => postLogMessage(1, "worker", ...args);
+  log.warn = (...args) => postLogMessage(2, "worker", ...args);
+  log.info = (...args) => postLogMessage(3, "worker", ...args);
+  log.debug = (...args) => postLogMessage(4, "worker", ...args);
+  log.trace = (...args) => postLogMessage(5, "worker", ...args);
+
   if (qscLogLevel !== undefined) {
     log.setLogLevel(qscLogLevel);
   }
 
   // Set up logging and telemetry as soon as possible after instantiating
   log.onLevelChanged = (level) => wasm.setLogLevel(level);
-  log.setTelemetryCollector(telemetryHandler);
-  wasm.initLogging(log.logWithLevel, log.getLogLevel());
+  log.setTelemetryCollector(postTelemetryMessage);
+  wasm.initLogging(postLogMessage, log.getLogLevel());
 
   // Create the actual service and return the dispatcher method
   const service = new serviceProtocol.class(wasm);

wasm/src/logging.rs

@@ -16,6 +16,12 @@ extern "C" {
 
     #[wasm_bindgen(structural, method, getter)]
     fn stack(error: &Error) -> String;
+
+    #[wasm_bindgen(static_method_of = Error, getter = stackTraceLimit)]
+    fn get_stack_trace_limit() -> Option<u32>;
+
+    #[wasm_bindgen(static_method_of = Error, setter = stackTraceLimit)]
+    fn set_stack_trace_limit(val: u32);
 }
 
 static MY_LOGGER: MyLogger = MyLogger;
@@ -65,7 +71,14 @@ pub fn hook(info: &std::panic::PanicInfo) {
     // for capturing the JS stack as well as the panic info
     let mut msg = info.to_string();
     msg.push_str("\n\nStack:\n\n");
+
+    // In debug builds, the logging and panic handling code itself takes
+    // up over 10 frames. Increase the stack trace limit temporarily.
+    let prev_limit = Error::get_stack_trace_limit().unwrap_or(10);
+    Error::set_stack_trace_limit(prev_limit.max(20));
     let e = Error::new();
+    Error::set_stack_trace_limit(prev_limit);
+
     let stack = e.stack();
     msg.push_str(&stack);
     msg.push_str("\n\n");