Bob Aman (Feb 21 2024 at 19:50): Bob Aman (Feb 21 2024 at 19:50):With wasi 0.2.0, I opted to redesign my guest API to use wasi-http. Unfortunately, I'm running into some issues with incoming-response in particular. My guest environment can read an incoming-request body just fine, but the same code to read a response body fails trying to consume() the body. There doesn't seem to be an error type to help diagnose the problem, so I'm not sure what I've done wrong. Notably, this doesn't use incoming-handler because the guest doesn't produce a response itself but rather makes security decisions based on requests/responses. I'm also currently reading everything into a buffer ahead of time because the same request/response have to be sent to multiple guest environments.
Code's public. Here's the bits I suspect are most relevant:
https://github.com/bulwark-security/bulwark/blob/api-refactor/wit/handlers.wit#L32
https://github.com/bulwark-security/bulwark/blob/api-refactor/crates/wasm-host/src/plugin.rs#L475-L493
https://github.com/bulwark-security/bulwark/blob/api-refactor/crates/wasm-sdk-macros/src/lib.rs#L402-L411
Sample output for a single guest plugin:
INFO handle request [ 3.42ms | 0.00% / 100.00% ]
INFO ┕━ route request [ 3.42ms | 30.54% / 100.00% ]
INFO ┝━ ｉ [info]: "process request" | method: "POST" | uri: "/echo" | user_agent: "curl/8.1.2"
INFO ┝━ execute on_init [ 277µs | 8.12% ]
INFO ┝━ execute on_request [ 1.40ms | 41.03% ]
INFO ┝━ execute on_request_decision [ 243µs | 7.11% ]
INFO │ ┕━ ｉ [info]: "plugin decision" | name: "blank_slate" | accept: 0.0 | restrict: 0.0 | unknown: 1.0 | score: 0.5 | weight: 1.0
INFO ┝━ ｉ [info]: "combine decision" | accept: 0.0 | restrict: 0.0 | unknown: 1.0 | score: 0.5 | outcome: "accepted" | observe_only: true | tags: "blank-slate"
INFO ┝━ execute on_response_decision [ 326µs | 9.52% ]
ERROR │ ┕━ 🚨 [error]: "plugin error" | error: "Error::Other(\"body cannot be consumed\")"
ERROR ┝━ 🚨 [error]: "plugin execution error" | elapsed: HandlerError(Error::Other("body cannot be consumed"))
INFO ┝━ ｉ [info]: "combine decision" | accept: 0.0 | restrict: 0.0 | unknown: 1.0 | score: 0.5 | outcome: "accepted" | observe_only: true | tags: "error"
INFO ┝━ ｉ [info]: "process response" | status: 200
INFO ┝━ execute on_decision_feedback [ 108µs | 3.15% ]
ERROR ┝━ 🚨 [error]: "plugin execution error" | elapsed: HandlerError(Error::Other("body cannot be consumed"))
INFO ┕━ plugin output [ 18.1µs | 0.53% ]
The last several issues I've run into have turned out to be blindingly obvious to other people, and I'm hoping this is another in that category since I don't seem to be making any headway myself at this point. Would anyone be willing to take a look?
Till Schneidereit (Feb 22 2024 at 18:00):one thing you could try is to get Wasmtime to give you more information. You should be able to do so by adding this before your invocation:
RUST_LOG="error,wasmtime_wasi=trace"
(If that doesn't work, try WASMTIME_LOG instead)
Bob Aman (Feb 22 2024 at 18:47):Unfortunately that just tells me what I already know, but in more detail. The incoming-response's body consume() is unsuccessful, but the incoming-request is fine.
INFO handle request [ 10.2ms | 0.00% / 100.00% ]
INFO ┕━ route request [ 10.2ms | 0.00% / 100.00% ]
INFO ┝━ ｉ [info]: "process request" | method: "POST" | uri: "/echo" | user_agent: "curl/8.1.2"
[snip]
INFO ┝━ execute on_response_decision [ 803µs | 7.02% / 7.86% ]
TRACE │ ┝━ wit-bindgen import [ 5.90µs | 0.06% ] module: "types" | function: "[method]incoming-request.scheme"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 3, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok(None)
TRACE │ ┝━ wit-bindgen import [ 3.42µs | 0.03% ] module: "types" | function: "[method]incoming-request.authority"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 3, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok(None)
TRACE │ ┝━ wit-bindgen import [ 4.88µs | 0.05% ] module: "types" | function: "[method]incoming-request.method"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 3, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok(Method::Post)
TRACE │ ┝━ wit-bindgen import [ 3.30µs | 0.03% ] module: "types" | function: "[method]incoming-request.path-with-query"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 3, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok(Some("/echo"))
TRACE │ ┝━ wit-bindgen import [ 4.38µs | 0.04% ] module: "types" | function: "[method]incoming-request.headers"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 3, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok(Resource { rep: 5, state: "own (not in table)" })
TRACE │ ┝━ wit-bindgen import [ 13.8µs | 0.13% ] module: "types" | function: "[method]fields.entries"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 5, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok([("user-agent", [99, 117, 114, 108, 47, 56, 46, 49, 46, 50]), ("accept", [42, 47, 42]), ("content-length", [52]), ("content-type", [97, 112, 112, 108, 105, 99, 97, 116, 105, 111, 110, 47, 120, 45, 119, 119, 119, 45, 102, 111, 114, 109, 45, 117, 114, 108, 101, 110, 99, 111, 100, 101, 100]), ("x-forwarded-proto", [104, 116, 116, 112]), ("x-request-id", [50, 57, 102, 55, 54, 99, 57, 101, 45, 52, 50, 50, 57, 45, 52, 56, 55, 57, 45, 97, 100, 99, 57, 45, 101, 97, 55, 57, 54, 56, 56, 98, 57, 56, 57, 49])])
TRACE │ ┝━ wit-bindgen import [ 4.30µs | 0.04% ] module: "types" | function: "[method]incoming-request.consume"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 3, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok(Ok(Resource { rep: 5, state: "own (not in table)" }))
TRACE │ ┝━ wit-bindgen import [ 4.39µs | 0.04% ] module: "types" | function: "[method]incoming-body.stream"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 5, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok(Ok(Resource { rep: 6, state: "own (not in table)" }))
TRACE │ ┝━ wit-bindgen import [ 10.6µs | 0.10% ] module: "streams" | function: "[method]input-stream.read"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 6, state: "borrow" } | len: 1048576
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok([116, 101, 115, 116])
TRACE │ ┝━ wit-bindgen import [ 6.61µs | 0.06% ] module: "types" | function: "[method]incoming-response.status"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 4, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok(200)
TRACE │ ┝━ wit-bindgen import [ 8.09µs | 0.08% ] module: "types" | function: "[method]incoming-response.headers"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 4, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok(Resource { rep: 3, state: "own (not in table)" })
TRACE │ ┝━ wit-bindgen import [ 11.1µs | 0.11% ] module: "types" | function: "[method]fields.entries"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 3, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok([("content-type", [97, 112, 112, 108, 105, 99, 97, 116, 105, 111, 110, 47, 120, 45, 119, 119, 119, 45, 102, 111, 114, 109, 45, 117, 114, 108, 101, 110, 99, 111, 100, 101, 100]), ("content-length", [52]), ("date", [84, 104, 117, 44, 32, 50, 50, 32, 70, 101, 98, 32, 50, 48, 50, 52, 32, 49, 56, 58, 51, 49, 58, 53, 53, 32, 71, 77, 84]), ("x-envoy-upstream-service-time", [49])])
TRACE │ ┝━ wit-bindgen import [ 4.80µs | 0.05% ] module: "types" | function: "[method]incoming-response.consume"
TRACE │ │ ┝━ 📍 [trace]: call | self_: Resource { rep: 4, state: "borrow" }
TRACE │ │ ┕━ 📍 [trace]: return | result: Ok(Err(()))
ERROR │ ┕━ 🚨 [error]: "plugin error" | error: "Error::Other(\"body cannot be consumed\")"
ERROR ┝━ 🚨 [error]: "plugin execution error" | elapsed: HandlerError(Error::Other("body cannot be consumed"))
INFO ┝━ ｉ [info]: "combine decision" | accept: 0.0 | restrict: 0.0 | unknown: 1.0 | score: 0.5 | outcome: "accepted" | observe_only: true | tags: "error"
INFO ┝━ ｉ [info]: "process response" | status: 200
I wondered if maybe something additional needed to happen w/ the incoming-body resource that I'm not doing, but I didn't see anything in the equivalent code for WasiHttpView's new_incoming_request implementation to suggest it.
Bob Aman (Feb 22 2024 at 19:02):For additional context, new_incoming_request originates with the wasmtime-wasi-http dependency, while new_incoming_response is my own code. I was a little surprised that it didn't already exist, but maybe it's more typical for those to be coming in from an outgoing handler?
Till Schneidereit (Feb 22 2024 at 21:28):hmm, my best guess would be that the problem is in that implementation—that somehow what you're creating doesn't support the wasi-http implementation's expectations for doing the consume operation on it
Bob Aman (Feb 22 2024 at 23:34):Yeah, that's essentially what I've been trying to do — deduce what those expectations are, since I haven't found any documentation that seems to lay it out. I've been trying to go through every piece of code I could find that touches wasmtime_wasi_http::types::HostIncomingResponse or wasmtime_wasi_http::body::HostIncomingBody, but I'm not sure I'm much closer to understanding the expectations at this point. It seems like there's a lot more documentation for consuming a body than provisioning one for consumption.
Bob Aman (Feb 23 2024 at 19:17):Dug in a bit further. Looking at this code snippet inside the wasmtime-wasi-http consume() implementation, a body value of None, always results in an error.
match r.body.take() {
Some(body) => {
let id = self.table().push(body)?;
Ok(Ok(id))
}
None => Ok(Err(())),
}
It looks like there were two issues that combined to make for something harder-to-debug.
Option<HostIncomingBody> on HostIncomingResponse wasn't documented and I incorrectly assumed a None here would represent something like a response to a HEAD request. Instead it seems to be an error condition, possibly used when the body was already consumed? Not sure?Thanks for the help!
Last updated: Dec 23 2024 at 12:05 UTC