Stream: git-wasmtime

Topic: wasmtime / issue #10122 Wasmtime should always print gues...

Wasmtime GitHub notifications bot (Jan 27 2025 at 16:22):

tschneidereit added the enhancement label to Issue #10122.

Wasmtime GitHub notifications bot (Jan 27 2025 at 16:22):

tschneidereit opened issue #10122:

Feature

Currently, Wasmtime doesn't always print anything to stderr when the guest panics: e.g. when serving incoming HTTP requests, panics are only printed if they happen before a response is sent. If the panic happens after the response headers have been sent, the panic is silently swallowed, and will only show up with the right WASMTIME_LOG incantation.

Benefit

Make guest panics easier to identify and debug.

Implementation

I'm not sure where this needs to be added, unfortunately.

Alternatives

Do nothing.

Wasmtime GitHub notifications bot (Jan 27 2025 at 16:23):

tschneidereit added the wasmtime label to Issue #10122.

Wasmtime GitHub notifications bot (Jan 27 2025 at 18:07):

alexcrichton commented on issue #10122:

Do you have an example to run? Glancing at the logging in wasmtime serve it looks like it's writing everything to stdout/stderr as soon as it gets it, so I'm not immediately sure where the issue might lie.

Wasmtime GitHub notifications bot (Feb 22 2025 at 14:16):

primoly commented on issue #10122:

When a component traps before calling set, receiver.await has an error and this code is invoked
https://github.com/bytecodealliance/wasmtime/blob/2e48fbc9279f89d89f4dd99c48da48e2735e18cc/src/commands/serve.rs#L537
and the underlying cause of the failure of the task is retrieved.

But when it traps afterwards, receiver.await returns Ok, this code is executed
https://github.com/bytecodealliance/wasmtime/blob/2e48fbc9279f89d89f4dd99c48da48e2735e18cc/src/commands/serve.rs#L526
causing the error from the task to get discarded.

The code currently makes two wrong assumptions:

1. An error in receiver means an error in task.
2. Success in receiver means success in task.

(1) has been fixed in #10256, but @tschneidereit’s problem (2) hasn’t yet.

Here a proxy component to try at home. It traps after calling set (line 117). To see the difference of trapping before, uncomment ;; unreachable on line 91.

<details><summary>proxy.wat</summary>

(component
  (type (;0;)
    (instance
      (export (;0;) "error" (type (sub resource)))
    )
  )
  (import "wasi:io/error@0.2.0" (instance (;0;) (type 0)))
  (alias export 0 "error" (type (;1;)))
  (type (;2;)
    (instance
      (export (;0;) "output-stream" (type (sub resource)))
      (alias outer 1 1 (type (;1;)))
      (export (;2;) "error" (type (eq 1)))
      (type (;3;) (own 2))
      (type (;4;) (variant (case "last-operation-failed" 3) (case "closed")))
      (export (;5;) "stream-error" (type (eq 4)))
      (type (;6;) (borrow 0))
      (type (;7;) (list u8))
      (type (;8;) (result (error 5)))
      (type (;9;) (func (param "self" 6) (param "contents" 7) (result 8)))
      (export (;0;) "[method]output-stream.blocking-write-and-flush" (func (type 9)))
    )
  )
  (import "wasi:io/streams@0.2.0" (instance (;1;) (type 2)))
  (alias export 1 "output-stream" (type (;3;)))
  (type (;4;)
    (instance
      (export (;0;) "fields" (type (sub resource)))
      (export (;1;) "response-outparam" (type (sub resource)))
      (export (;2;) "outgoing-response" (type (sub resource)))
      (type (;3;) (option string))
      (type (;4;) (option u16))
      (type (;5;) (record (field "rcode" 3) (field "info-code" 4)))
      (export (;6;) "DNS-error-payload" (type (eq 5)))
      (type (;7;) (option u8))
      (type (;8;) (record (field "alert-id" 7) (field "alert-message" 3)))
      (export (;9;) "TLS-alert-received-payload" (type (eq 8)))
      (type (;10;) (option u32))
      (type (;11;) (record (field "field-name" 3) (field "field-size" 10)))
      (export (;12;) "field-size-payload" (type (eq 11)))
      (type (;13;) (option u64))
      (type (;14;) (option 12))
      (type (;15;) (variant (case "DNS-timeout") (case "DNS-error" 6) (case "destination-not-found") (case "destination-unavailable") (case "destination-IP-prohibited") (case "destination-IP-unroutable") (case "connection-refused") (case "connection-terminated") (case "connection-timeout") (case "connection-read-timeout") (case "connection-write-timeout") (case "connection-limit-reached") (case "TLS-protocol-error") (case "TLS-certificate-error") (case "TLS-alert-received" 9) (case "HTTP-request-denied") (case "HTTP-request-length-required") (case "HTTP-request-body-size" 13) (case "HTTP-request-method-invalid") (case "HTTP-request-URI-invalid") (case "HTTP-request-URI-too-long") (case "HTTP-request-header-section-size" 10) (case "HTTP-request-header-size" 14) (case "HTTP-request-trailer-section-size" 10) (case "HTTP-request-trailer-size" 12) (case "HTTP-response-incomplete") (case "HTTP-response-header-section-size" 10) (case "HTTP-response-header-size" 12) (case "HTTP-response-body-size" 13) (case "HTTP-response-trailer-section-size" 10) (case "HTTP-response-trailer-size" 12) (case "HTTP-response-transfer-coding" 3) (case "HTTP-response-content-coding" 3) (case "HTTP-response-timeout") (case "HTTP-upgrade-failed") (case "HTTP-protocol-error") (case "loop-detected") (case "configuration-error") (case "internal-error" 3)))
      (export (;16;) "error-code" (type (eq 15)))
      (export (;17;) "headers" (type (eq 0)))
      (export (;18;) "outgoing-body" (type (sub resource)))
      (alias outer 1 3 (type (;19;)))
      (export (;20;) "output-stream" (type (eq 19)))
      (export (;21;) "incoming-request" (type (sub resource)))
      (type (;22;) (own 0))
      (type (;23;) (func (result 22)))
      (export (;0;) "[constructor]fields" (func (type 23)))
      (type (;24;) (own 1))
      (type (;25;) (own 2))
      (type (;26;) (result 25 (error 16)))
      (type (;27;) (func (param "param" 24) (param "response" 26)))
      (export (;1;) "[static]response-outparam.set" (func (type 27)))
      (type (;28;) (own 17))
      (type (;29;) (func (param "headers" 28) (result 25)))
      (export (;2;) "[constructor]outgoing-response" (func (type 29)))
      (type (;30;) (borrow 2))
      (type (;31;) (own 18))
      (type (;32;) (result 31))
      (type (;33;) (func (param "self" 30) (result 32)))
      (export (;3;) "[method]outgoing-response.body" (func (type 33)))
      (type (;34;) (borrow 18))
      (type (;35;) (own 20))
      (type (;36;) (result 35))
      (type (;37;) (func (param "self" 34) (result 36)))
      (export (;4;) "[method]outgoing-body.write" (func (type 37)))
    )
  )
  (import "wasi:http/types@0.2.0" (instance (;2;) (type 4)))
  (core module (;0;)
    (type (;0;) (func (param i32 i32 i32 i32)))
    (type (;1;) (func (param i32 i32 i32 i32 i64 i32 i32 i32 i32)))
    (type (;2;) (func (result i32)))
    (type (;3;) (func (param i32) (result i32)))
    (type (;4;) (func (param i32 i32)))
    (import "cm32p2|wasi:io/streams@0.2" "[method]output-stream.blocking-write-and-flush" (func $write (;0;) (type 0)))
    (import "cm32p2|wasi:http/types@0.2" "[static]response-outparam.set" (func $set (;1;) (type 1)))
    (import "cm32p2|wasi:http/types@0.2" "[constructor]fields" (func $headers (;2;) (type 2)))
    (import "cm32p2|wasi:http/types@0.2" "[constructor]outgoing-response" (func $out-res (;3;) (type 3)))
    (import "cm32p2|wasi:http/types@0.2" "[method]outgoing-response.body" (func $body (;4;) (type 4)))
    (import "cm32p2|wasi:http/types@0.2" "[method]outgoing-body.write" (func $body-write (;5;) (type 4)))
    (memory (;0;) 1)
    (export "cm32p2_memory" (memory 0))
    (export "cm32p2|wasi:http/incoming-handler@0.2|handle" (func 6))
    (func (;6;) (type 4) (param i32) (param $out-param i32)
      (local $res i32)
      ;; unreachable
      call $headers
      call $out-res
      local.tee $res
      i32.const 256
      call $body
      local.get $out-param
      i32.const 0
      local.get $res
      i32.const 0
      i64.const 0
      i32.const 0
      i32.const 0
      i32.const 0
      i32.const 0
      call $set
      i32.const 260
      i32.load
      i32.const 256
      call $body-write
      i32.const 260
      i32.load
      i32.const 16
      i32.const 25
      i32.const 512
      call $write
      unreachable
    )
    (data (;0;) (i32.const 16) "Hello from the other side.\0a")
    (@producers
      (processed-by "wit-component" "0.225.0")
    )
  )
  (core module (;1;)
    (type (;0;) (func (param i32 i32 i32 i32)))
    (type (;1;) (func (param i32 i32 i32 i32 i64 i32 i32 i32 i32)))
    (type (;2;) (func (param i32 i32)))
    (table (;0;) 4 4 funcref)
    (export "0" (func $"indirect-cm32p2|wasi:io/streams@0.2-[method]output-stream.blocking-write-and-flush"))
    (export "1" (func $"indirect-cm32p2|wasi:http/types@0.2-[static]response-outparam.set"))
    (export "2" (func $"indirect-cm32p2|wasi:http/types@0.2-[method]outgoing-response.body"))
    (export "3" (func $"indirect-cm32p2|wasi:http/types@0.2-[method]outgoing-body.write"))
    (export "$imports" (table 0))
    (func $"indirect-cm32p2|wasi:io/streams@0.2-[method]output-stream.blocking-write-and-flush" (;0;) (type 0) (param i32 i32 i32 i32)
      local.get 0
      local.get 1
      local.get 2
      local.get 3
      i32.const 0
      call_indirect (type 0)
    )
    (func $"indirect-cm32p2|wasi:http/types@0.2-[static]response-outparam.set" (;1;) (type 1) (param i32 i32 i32 i32 i64 i32 i32 i32 i32)
      local.get 0
      local.get 1
      local.get 2
      local.get 3
      local.get 4
      local.get 5
      local.get 6
      local.get 7
      local.get 8
      i32.const 1
      call_indirect (type 1)
    )
    (func $"indirect-cm32p2|wasi:http/types@0.2-[method]outgoing-response.body" (;2;) (type 2) (param i32 i32)
      local.get 0
      local.get 1
      i32.const 2
      call_indirect (type 2)
    )
    (func $"indirect-cm32p2|wasi:http/types@0.2-[method]outgoing-body.write" (;3;) (type 2) (param i32 i32)
      local.get 0
      local.get 1
      i32.const 3
      call_indirect (type 2)
    )
    (@producers
      (processed-by "wit-component" "0.225.0")
    )
  )
  (core module (;2;)
    (type (;0;) (func (param i32 i32 i32 i32)))
    (type (;1;) (func (param i32 i32 i32 i32 i64 i32 i32 i32 i32)))
    (type (;2;) (func (param i32 i32)))
    (import "" "0" (func (;0;) (type 0)))
    (import "" "1" (func (;1;) (type 1)))
    (import "" "2" (func (;2;) (type 2)))
    (import "" "3" (func (;3;) (type 2)))
    (import "" "$imports" (table (;0;) 4 4 funcref))
    (elem (;0;) (i32.const 0) func 0 1 2 3)
    (@producers
      (processed-by "wit-component" "0.225.0")
    )
  )
  (core instance (;0;) (instantiate 1))
  (alias core export 0 "0" (core func (;0;)))
  (core instance (;1;)
    (export "[method]output-stream.blocking-write-and-flush" (func 0))
  )
  (alias core export 0 "1" (core func (;1;)))
  (alias export 2 "[constructor]fields" (func (;0;)))
  (core func (;2;) (canon lower (func 0)))
  (alias export 2 "[constructor]outgoing-response" (func (;1;)))
  (core func (;3;) (canon lower (func
[message truncated]

Wasmtime GitHub notifications bot (Feb 22 2025 at 15:25):

primoly edited a comment on issue #10122:

When a component traps before calling set, receiver.await has an error and this code is invoked
https://github.com/bytecodealliance/wasmtime/blob/2e48fbc9279f89d89f4dd99c48da48e2735e18cc/src/commands/serve.rs#L537
and the underlying cause of the failure of the task is retrieved.

But when it traps afterwards, receiver.await returns Ok, this code is executed
https://github.com/bytecodealliance/wasmtime/blob/2e48fbc9279f89d89f4dd99c48da48e2735e18cc/src/commands/serve.rs#L526
causing the error from the task to get discarded.

The code currently makes two wrong assumptions:

1. An error in receiver means an error in task.
2. Success in receiver means success in task.

(1) has been fixed in #10256, but @tschneidereit’s problem (2) hasn’t yet.

Here a proxy component to try at home. It traps after calling set (line 117). To see the difference of trapping before, uncomment ;; unreachable on line 91.

<details><summary>proxy.wat</summary>

(component
  (type (;0;)
    (instance
      (export (;0;) "error" (type (sub resource)))
    )
  )
  (import "wasi:io/error@0.2.0" (instance (;0;) (type 0)))
  (alias export 0 "error" (type (;1;)))
  (type (;2;)
    (instance
      (export (;0;) "output-stream" (type (sub resource)))
      (alias outer 1 1 (type (;1;)))
      (export (;2;) "error" (type (eq 1)))
      (type (;3;) (own 2))
      (type (;4;) (variant (case "last-operation-failed" 3) (case "closed")))
      (export (;5;) "stream-error" (type (eq 4)))
      (type (;6;) (borrow 0))
      (type (;7;) (list u8))
      (type (;8;) (result (error 5)))
      (type (;9;) (func (param "self" 6) (param "contents" 7) (result 8)))
      (export (;0;) "[method]output-stream.blocking-write-and-flush" (func (type 9)))
    )
  )
  (import "wasi:io/streams@0.2.0" (instance (;1;) (type 2)))
  (alias export 1 "output-stream" (type (;3;)))
  (type (;4;)
    (instance
      (export (;0;) "fields" (type (sub resource)))
      (export (;1;) "response-outparam" (type (sub resource)))
      (export (;2;) "outgoing-response" (type (sub resource)))
      (type (;3;) (option string))
      (type (;4;) (option u16))
      (type (;5;) (record (field "rcode" 3) (field "info-code" 4)))
      (export (;6;) "DNS-error-payload" (type (eq 5)))
      (type (;7;) (option u8))
      (type (;8;) (record (field "alert-id" 7) (field "alert-message" 3)))
      (export (;9;) "TLS-alert-received-payload" (type (eq 8)))
      (type (;10;) (option u32))
      (type (;11;) (record (field "field-name" 3) (field "field-size" 10)))
      (export (;12;) "field-size-payload" (type (eq 11)))
      (type (;13;) (option u64))
      (type (;14;) (option 12))
      (type (;15;) (variant (case "DNS-timeout") (case "DNS-error" 6) (case "destination-not-found") (case "destination-unavailable") (case "destination-IP-prohibited") (case "destination-IP-unroutable") (case "connection-refused") (case "connection-terminated") (case "connection-timeout") (case "connection-read-timeout") (case "connection-write-timeout") (case "connection-limit-reached") (case "TLS-protocol-error") (case "TLS-certificate-error") (case "TLS-alert-received" 9) (case "HTTP-request-denied") (case "HTTP-request-length-required") (case "HTTP-request-body-size" 13) (case "HTTP-request-method-invalid") (case "HTTP-request-URI-invalid") (case "HTTP-request-URI-too-long") (case "HTTP-request-header-section-size" 10) (case "HTTP-request-header-size" 14) (case "HTTP-request-trailer-section-size" 10) (case "HTTP-request-trailer-size" 12) (case "HTTP-response-incomplete") (case "HTTP-response-header-section-size" 10) (case "HTTP-response-header-size" 12) (case "HTTP-response-body-size" 13) (case "HTTP-response-trailer-section-size" 10) (case "HTTP-response-trailer-size" 12) (case "HTTP-response-transfer-coding" 3) (case "HTTP-response-content-coding" 3) (case "HTTP-response-timeout") (case "HTTP-upgrade-failed") (case "HTTP-protocol-error") (case "loop-detected") (case "configuration-error") (case "internal-error" 3)))
      (export (;16;) "error-code" (type (eq 15)))
      (export (;17;) "headers" (type (eq 0)))
      (export (;18;) "outgoing-body" (type (sub resource)))
      (alias outer 1 3 (type (;19;)))
      (export (;20;) "output-stream" (type (eq 19)))
      (export (;21;) "incoming-request" (type (sub resource)))
      (type (;22;) (own 0))
      (type (;23;) (func (result 22)))
      (export (;0;) "[constructor]fields" (func (type 23)))
      (type (;24;) (own 1))
      (type (;25;) (own 2))
      (type (;26;) (result 25 (error 16)))
      (type (;27;) (func (param "param" 24) (param "response" 26)))
      (export (;1;) "[static]response-outparam.set" (func (type 27)))
      (type (;28;) (own 17))
      (type (;29;) (func (param "headers" 28) (result 25)))
      (export (;2;) "[constructor]outgoing-response" (func (type 29)))
      (type (;30;) (borrow 2))
      (type (;31;) (own 18))
      (type (;32;) (result 31))
      (type (;33;) (func (param "self" 30) (result 32)))
      (export (;3;) "[method]outgoing-response.body" (func (type 33)))
      (type (;34;) (borrow 18))
      (type (;35;) (own 20))
      (type (;36;) (result 35))
      (type (;37;) (func (param "self" 34) (result 36)))
      (export (;4;) "[method]outgoing-body.write" (func (type 37)))
    )
  )
  (import "wasi:http/types@0.2.0" (instance (;2;) (type 4)))
  (core module (;0;)
    (type (;0;) (func (param i32 i32 i32 i32)))
    (type (;1;) (func (param i32 i32 i32 i32 i64 i32 i32 i32 i32)))
    (type (;2;) (func (result i32)))
    (type (;3;) (func (param i32) (result i32)))
    (type (;4;) (func (param i32 i32)))
    (import "cm32p2|wasi:io/streams@0.2" "[method]output-stream.blocking-write-and-flush" (func $write (;0;) (type 0)))
    (import "cm32p2|wasi:http/types@0.2" "[static]response-outparam.set" (func $set (;1;) (type 1)))
    (import "cm32p2|wasi:http/types@0.2" "[constructor]fields" (func $headers (;2;) (type 2)))
    (import "cm32p2|wasi:http/types@0.2" "[constructor]outgoing-response" (func $out-res (;3;) (type 3)))
    (import "cm32p2|wasi:http/types@0.2" "[method]outgoing-response.body" (func $body (;4;) (type 4)))
    (import "cm32p2|wasi:http/types@0.2" "[method]outgoing-body.write" (func $body-write (;5;) (type 4)))
    (memory (;0;) 1)
    (export "cm32p2_memory" (memory 0))
    (export "cm32p2|wasi:http/incoming-handler@0.2|handle" (func 6))
    (func (;6;) (type 4) (param i32) (param $out-param i32)
      (local $res i32)
      ;; unreachable
      call $headers
      call $out-res
      local.tee $res
      i32.const 256
      call $body
      local.get $out-param
      i32.const 0
      local.get $res
      i32.const 0
      i64.const 0
      i32.const 0
      i32.const 0
      i32.const 0
      i32.const 0
      call $set
      i32.const 260
      i32.load
      i32.const 256
      call $body-write
      i32.const 260
      i32.load
      i32.const 16
      i32.const 27
      i32.const 512
      call $write
      unreachable
    )
    (data (;0;) (i32.const 16) "Hello from the other side.\0a")
  )
  (core module (;1;)
    (type (;0;) (func (param i32 i32 i32 i32)))
    (type (;1;) (func (param i32 i32 i32 i32 i64 i32 i32 i32 i32)))
    (type (;2;) (func (param i32 i32)))
    (table (;0;) 4 4 funcref)
    (export "0" (func $"indirect-cm32p2|wasi:io/streams@0.2-[method]output-stream.blocking-write-and-flush"))
    (export "1" (func $"indirect-cm32p2|wasi:http/types@0.2-[static]response-outparam.set"))
    (export "2" (func $"indirect-cm32p2|wasi:http/types@0.2-[method]outgoing-response.body"))
    (export "3" (func $"indirect-cm32p2|wasi:http/types@0.2-[method]outgoing-body.write"))
    (export "$imports" (table 0))
    (func $"indirect-cm32p2|wasi:io/streams@0.2-[method]output-stream.blocking-write-and-flush" (;0;) (type 0) (param i32 i32 i32 i32)
      local.get 0
      local.get 1
      local.get 2
      local.get 3
      i32.const 0
      call_indirect (type 0)
    )
    (func $"indirect-cm32p2|wasi:http/types@0.2-[static]response-outparam.set" (;1;) (type 1) (param i32 i32 i32 i32 i64 i32 i32 i32 i32)
      local.get 0
      local.get 1
      local.get 2
      local.get 3
      local.get 4
      local.get 5
      local.get 6
      local.get 7
      local.get 8
      i32.const 1
      call_indirect (type 1)
    )
    (func $"indirect-cm32p2|wasi:http/types@0.2-[method]outgoing-response.body" (;2;) (type 2) (param i32 i32)
      local.get 0
      local.get 1
      i32.const 2
      call_indirect (type 2)
    )
    (func $"indirect-cm32p2|wasi:http/types@0.2-[method]outgoing-body.write" (;3;) (type 2) (param i32 i32)
      local.get 0
      local.get 1
      i32.const 3
      call_indirect (type 2)
    )
  )
  (core module (;2;)
    (type (;0;) (func (param i32 i32 i32 i32)))
    (type (;1;) (func (param i32 i32 i32 i32 i64 i32 i32 i32 i32)))
    (type (;2;) (func (param i32 i32)))
    (import "" "0" (func (;0;) (type 0)))
    (import "" "1" (func (;1;) (type 1)))
    (import "" "2" (func (;2;) (type 2)))
    (import "" "3" (func (;3;) (type 2)))
    (import "" "$imports" (table (;0;) 4 4 funcref))
    (elem (;0;) (i32.const 0) func 0 1 2 3)
  )
  (core instance (;0;) (instantiate 1))
  (alias core export 0 "0" (core func (;0;)))
  (core instance (;1;)
    (export "[method]output-stream.blocking-write-and-flush" (func 0))
  )
  (alias core export 0 "1" (core func (;1;)))
  (alias export 2 "[constructor]fields" (func (;0;)))
  (core func (;2;) (canon lower (func 0)))
  (alias export 2 "[constructor]outgoing-response" (func (;1;)))
  (core func (;3;) (canon lower (func 1)))
  (alias core export 0 "2" (core func (;4;)))
  (alias core export 0 "3" (core func (;5;)))
  (core instance (;2;)
    (export "[static]response-outparam.set" (func 1))
    (export "[constructor]
[message truncated]

Wasmtime GitHub notifications bot (Feb 24 2025 at 15:54):

alexcrichton commented on issue #10122:

I think I'm still not quite following. I tried this test in Wasmtime's repository:

impl proxy::exports::wasi::http::incoming_handler::Guest for T {
    fn handle(_: IncomingRequest, outparam: ResponseOutparam) {
        let fields = Fields::new();
        let resp = OutgoingResponse::new(fields);

        ResponseOutparam::set(outparam, Ok(resp));

        panic!("what");
    }
}

and I got:

Serving HTTP on http://0.0.0.0:8080/
stderr [0] ::
stderr [0] :: thread '<unnamed>' panicked at crates/test-programs/src/bin/cli_serve_panic_after_set.rs:18:9:
stderr [0] :: what
stderr [0] :: note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
2025-02-24T15:50:45.303636Z ERROR wasmtime_cli::commands::serve: [0] :: error while executing at wasm backtrace:
    0: 0xa177 - cli_serve_panic_after_set-0a3657b6bedfd56f.wasm!__rust_start_panic
    1: 0xa0c9 - cli_serve_panic_after_set-0a3657b6bedfd56f.wasm!rust_panic
    2: 0xa09c - cli_serve_panic_after_set-0a3657b6bedfd56f.wasm!std::panicking::rust_panic_with_hook::he1beb51ce54153b5
    3: 0x93c6 - cli_serve_panic_after_set-0a3657b6bedfd56f.wasm!std::panicking::begin_panic_handler::{{closure}}::hdbff82bd9d56f6f9
    4: 0x9300 - cli_serve_panic_after_set-0a3657b6bedfd56f.wasm!std::sys::backtrace::__rust_end_short_backtrace::h5bb26fcae04a79f5
    5: 0x9a30 - cli_serve_panic_after_set-0a3657b6bedfd56f.wasm!rust_begin_unwind
    6: 0xe8e8 - cli_serve_panic_after_set-0a3657b6bedfd56f.wasm!core::panicking::panic_fmt::h2781e55e5f70e742
    7: 0x1722 - cli_serve_panic_after_set-0a3657b6bedfd56f.wasm!<cli_serve_panic_after_set::T as test_programs::proxy::exports::wasi::http::incoming_handler::Guest>::handle::h92d89fc0d302a262
    8: 0x15ce - cli_serve_panic_after_set-0a3657b6bedfd56f.wasm!test_programs::proxy::exports::wasi::http::incoming_handler::_export_handle_cabi::hb366510da1a4a724
    9: 0x175f - cli_serve_panic_after_set-0a3657b6bedfd56f.wasm!wasi:http/incoming-handler@0.2.3#handle
note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information

Caused by:
    wasm trap: wasm `unreachable` instruction executed

where both the stderr of the guest itself (the Rust-printed panic) as well as the trap (via ERROR) is printed by default. I think the ERROR can theoretically be suppressed with a different WASMTIME_LOG=... so we should perhaps fix that, but it's printed by default.

Here a proxy component to try at home. It traps after calling set (line 117). To see the difference of trapping before, uncomment ;; unreachable on line 91.

Could you clarify the expected behavior here? As-is I see the program prints that it traps and additionally returns the body, which is what I'd expect. If I uncomment the unreachable then I get nothing from curl (what I'd expect) and the console shows both the trap message and the message about not calling response-outparam::set

Wasmtime GitHub notifications bot (Feb 24 2025 at 18:21):

primoly commented on issue #10122:

In the trap before set case, you see the trap of the component reported twice:

Serving HTTP on http://0.0.0.0:8080/
2025-02-24T18:12:00.873347Z ERROR wasmtime_cli::commands::serve: [0] :: Error {
    context: "error while executing at wasm backtrace:\n    0:  0x975 - <unknown>!<wasm function 6>",
    source: UnreachableCodeReached,
}
error: hyper::Error(User(Service), guest never invoked `response-outparam::set` method: error while executing at wasm backtrace:
    0:  0x975 - <unknown>!<wasm function 6>

Caused by:
    wasm trap: wasm `unreachable` instruction executed)

The first is the ERROR …, which is triggered by

https://github.com/bytecodealliance/wasmtime/blob/3fb6dc72da1ae0237848beb3ed7619771cc705d4/src/commands/serve.rs#L518

while the second, error: … is caused by

https://github.com/bytecodealliance/wasmtime/blob/3fb6dc72da1ae0237848beb3ed7619771cc705d4/src/commands/serve.rs#L540

which reports both the error in hyper as well as the underlying unreachable in the component (Caused by: …).

When trapping after calling set, you get this output instead:

Serving HTTP on http://0.0.0.0:8080/
2025-02-24T18:13:53.563983Z ERROR wasmtime_cli::commands::serve: [0] :: Error {
    context: "error while executing at wasm backtrace:\n    0:  0x9ae - <unknown>!<wasm function 6>",
    source: UnreachableCodeReached,
}

Notice how the trap is reported just once, this time only by log::error.

And to get back to @tschneidereit’s original issue, you can use WASMTIME_LOG to enable or suppress that log, while the error is printed regardless.

Wasmtime GitHub notifications bot (Feb 24 2025 at 21:28):

alexcrichton commented on issue #10122:

That all makes sense to me yeah and matches what I'm seeing, but I feel like I'm still missing the connection from what's here to what the desired state of things is.

For example I don't think it's great that the trap is sometimes reported twice and sometimes once, but that seems like an orthogonal issue from @tschneidereit's issue which is about panics and stderr. In all cases so far stderr has never been swallowed and it's always been emitted.

I also think it's not great that you could set WASMTIME_LOG=off and have these traps entirely hidden, but that again seems orthogonal from the original issue.

@primoly are you perhaps saying that the trap should be reported once, and only once, and it shouldn't use log::error! and should instead us something like eprintln!?

Last updated: Feb 28 2025 at 03:10 UTC