search

proxy-wasm / proxy-wasm-rust-sdk

WebAssembly for Proxies (Rust SDK)
Apache License 2.0
495 stars 97 forks source link

on_http_request_body simply not called #241

Closed MarshHawk closed 4 months ago

MarshHawk commented 4 months ago

Testing the HttpContext handlers with a relatively simple implementation:

use log::info;
use proxy_wasm::traits::*;
use proxy_wasm::types::*;

#[no_mangle]
pub fn _start() {
    proxy_wasm::set_log_level(LogLevel::Info);
    proxy_wasm::set_http_context(|_, _| -> Box<dyn HttpContext> {
        Box::new(UpstreamCall::new())
    });
}

#[derive(Debug)]
struct UpstreamCall {}

impl UpstreamCall {
    fn new() -> Self {
        return Self {};
    }
}

impl HttpContext for UpstreamCall {
    fn on_http_request_headers(&mut self, _: usize, _: bool) -> Action {
        info!("on_http_request_headers");
        Action::Continue
    }

    fn on_http_request_body(&mut self, _body_size: usize, _end_of_stream: bool) -> Action {
        info!("on_http_request");
        Action::Continue
    }

    fn on_http_response_body(&mut self, _body_size: usize, _end_of_stream: bool) -> Action {
        info!("on_http_response");
        Action::Continue
    }
}

impl Context for UpstreamCall {}

impl RootContext for UpstreamCall {}

as the logs show, it's not hitting on_http_request_body

envoy-1  | [2024-07-02 01:10:33.719][16][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_request_headers
envoy-1  | [2024-07-02 01:10:33.719][16][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_response
envoy-1  | [2024-07-02 01:10:39.350][16][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_request_headers
envoy-1  | [2024-07-02 01:10:39.350][16][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_response
envoy-1  | [2024-07-02 01:23:28.166][16][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_request_headers
envoy-1  | [2024-07-02 01:23:28.167][16][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_response
envoy-1  | [2024-07-02 01:23:33.473][18][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_request_headers
envoy-1  | [2024-07-02 01:23:33.474][18][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_response

I'm trying a variety of curl (e.g. curl -X POST http://localhost:10000/hello -d '{"key":"value"}' -H "Content-Type: application/json")

And here is envoy.yaml:

static_resources:
  listeners:
    address:
      socket_address:
        address: 0.0.0.0
        port_value: 10000
    filter_chains:
      - filters:
          - name: envoy.filters.network.http_connection_manager
            typed_config:
              "@type": type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager
              stat_prefix: ingress_http
              codec_type: AUTO
              route_config:
                name: local_routes
                virtual_hosts:
                  - name: local_service
                    domains:
                      - "*"
                    routes:
                      - match:
                          prefix: "/"
                        direct_response:
                          status: 200
                          body:
                            inline_string: "Request /hello and be welcomed!\n"
              http_filters:
                - name: envoy.filters.http.wasm
                  typed_config:
                    "@type": type.googleapis.com/udpa.type.v1.TypedStruct
                    type_url: type.googleapis.com/envoy.extensions.filters.http.wasm.v3.Wasm
                    value:
                      config:
                        name: "body_proxy"
                        vm_config:
                          runtime: "envoy.wasm.runtime.v8"
                          code:
                            local:
                              filename: "/etc/envoy/body_proxy.wasm"
                - name: envoy.filters.http.router
                  typed_config:
                    "@type": type.googleapis.com/envoy.extensions.filters.http.router.v3.Router

It does not appear to be something obvious, is it?

PiotrSikora commented 4 months ago

I suspect that the direct_response in Envoy might be triggering a short path upon receiving HTTP headers, and later request callbacks are completely ignored.

Could you try using configuration without it?

MarshHawk commented 4 months ago

yes, ok, so it was obvious. I should have realized that. I verified it works without direct_response in the config:

envoy-1  | [2024-07-03 14:01:34.879][15][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_request_headers
envoy-1  | [2024-07-03 14:01:34.881][15][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_request
envoy-1  | [2024-07-03 14:01:34.881][15][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_request
envoy-1  | [2024-07-03 14:01:34.882][15][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_response
envoy-1  | [2024-07-03 14:03:50.261][16][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_request_headers
envoy-1  | [2024-07-03 14:03:50.261][16][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_request
envoy-1  | [2024-07-03 14:03:50.261][16][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_request
envoy-1  | [2024-07-03 14:03:50.262][16][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log body_proxy: on_http_response

Thank you!

liuxuzxx commented 2 months ago

My code is:

use log::info;
use log::trace;
use proxy_wasm::traits::*;
use proxy_wasm::types::*;

proxy_wasm::main! {{
    proxy_wasm::set_log_level(LogLevel::Info);
    proxy_wasm::set_root_context(|_| -> Box<dyn RootContext> { Box::new(HttpBodyRoot) });
}}

struct HttpBodyRoot;

impl Context for HttpBodyRoot {}

impl RootContext for HttpBodyRoot {
    fn get_type(&self) -> Option<ContextType> {
        Some(ContextType::HttpContext)
    }

    fn create_http_context(&self, _: u32) -> Option<Box<dyn HttpContext>> {
        Some(Box::new(HttpBody))
    }
}

struct HttpBody;

impl Context for HttpBody {}

impl HttpContext for HttpBody {
    fn on_http_response_headers(&mut self, _: usize, _: bool) -> Action {
        info!("Http Response Headers:Rust Proxy Wasm......");
        let headers = self.get_http_response_headers();
        for (name, value) in headers.iter() {
            info!("HTTP Response Header:{}---{}", name, value);
        }
        self.set_http_response_header("x-rust-liuxu-trust", Some("proxy-wasm-rust"));
        Action::Continue
    }

    fn on_http_response_body(&mut self, body_size: usize, end_of_stream: bool) -> Action {
        info!("获取响应的报文");
        if !end_of_stream {
            // Wait -- we'll be called again when the complete body is buffered
            // at the host side.
            return Action::Pause;
        }

        // Replace the message body if it contains the text "secret".
        // Since we returned "Pause" previuously, this will return the whole body.
        if let Some(body_bytes) = self.get_http_response_body(0, body_size) {
            let body_str = String::from_utf8(body_bytes).unwrap();
            info!("response body:{}", String::from("日志报文内容信息"));
            if body_str.contains("secret") {
                let new_body = format!("Original message body ({body_size} bytes) redacted.\n");
                self.set_http_response_body(0, body_size, &new_body.into_bytes());
            }
        }
        Action::Continue
    }

    fn on_http_request_headers(&mut self, _num_headers: usize, _end_of_stream: bool) -> Action {
        trace!("HTTP Request Headers:Rust Proxy Wasm的代码拦截......");
        info!("获取请求的heders information of request!");
        let headers = self.get_http_request_headers();
        for (name, value) in headers.iter() {
            info!("HTTP Request Header:{}---{}", name, value);
        }
        Action::Continue
    }

    fn on_http_request_body(&mut self, body_size: usize, end_of_stream: bool) -> Action {
        info!("获取请求的报文,fetch http request from http request body");
        if !end_of_stream {
            return Action::Pause;
        }
        if let Some(body_bytes) = self.get_http_request_body(0, body_size) {
            let body_str = String::from_utf8(body_bytes).unwrap();
            info!("request body:{}", body_str);
        }
        Action::Continue
    }
}

When use in envoy,envoy.yaml

static_resources:
  listeners:
    address:
      socket_address:
        address: 0.0.0.0
        port_value: 10000
    filter_chains:
      - filters:
          - name: envoy.filters.network.http_connection_manager
            typed_config:
              "@type": type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager
              stat_prefix: ingress_http
              access_log:
                - name: envoy.access_loggers.stdout
                  typed_config:
                    "@type": type.googleapis.com/envoy.extensions.access_loggers.stream.v3.StdoutAccessLog
              http_filters:
                - name: envoy.filters.http.wasm
                  typed_config:
                    "@type": type.googleapis.com/udpa.type.v1.TypedStruct
                    type_url: type.googleapis.com/envoy.extensions.filters.http.wasm.v3.Wasm
                    value:
                      config:
                        name: "http_body"
                        vm_config:
                          runtime: "envoy.wasm.runtime.v8"
                          code:
                            local:
                              filename: "/media/liuxu/data/code/github/rust-found/envoy-plugin/target/wasm32-unknown-unknown/release/envoy_plugin.wasm"
                - name: envoy.filters.http.router
                  typed_config:
                    "@type": type.googleapis.com/envoy.extensions.filters.http.router.v3.Router
              route_config:
                name: local_route
                virtual_hosts:
                  - name: local_service
                    domains: ["*"]
                    routes:
                      - match:
                          prefix: "/"
                        route:
                          host_rewrite_literal: www.baidu.com
                          cluster: service_envoyproxy_io

  clusters:
    - name: service_envoyproxy_io
      type: LOGICAL_DNS
      # Comment out the following line to test on v6 networks
      dns_lookup_family: V4_ONLY
      load_assignment:
        cluster_name: service_envoyproxy_io
        endpoints:
          - lb_endpoints:
              - endpoint:
                  address:
                    socket_address:
                      address: www.baidu.com
                      port_value: 443
      transport_socket:
        name: envoy.transport_sockets.tls
        typed_config:
          "@type": type.googleapis.com/envoy.extensions.transport_sockets.tls.v3.UpstreamTlsContext
          sni: www.baidu.com

The log is:

[2024-08-29 18:46:24.844][354563][info][main] [source/server/server.cc:969] starting main dispatch loop
[2024-08-29 18:46:24.844][354563][info][runtime] [source/common/runtime/runtime_impl.cc:614] RTDS has finished initialization
[2024-08-29 18:46:24.844][354563][info][upstream] [source/common/upstream/cluster_manager_impl.cc:240] cm init: all clusters initialized
[2024-08-29 18:46:24.844][354563][info][main] [source/server/server.cc:950] all clusters initialized. initializing init manager
[2024-08-29 18:46:24.844][354563][info][config] [source/common/listener_manager/listener_manager_impl.cc:930] all dependencies initialized. starting workers
[2024-08-29 18:46:35.538][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: 获取请求的heders information of request!
[2024-08-29 18:46:35.538][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Request Header::authority---localhost:10000
[2024-08-29 18:46:35.538][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Request Header::path---/
[2024-08-29 18:46:35.538][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Request Header::method---GET
[2024-08-29 18:46:35.538][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Request Header::scheme---http
[2024-08-29 18:46:35.538][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Request Header:user-agent---curl/8.5.0
[2024-08-29 18:46:35.538][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Request Header:accept---*/*
[2024-08-29 18:46:35.538][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Request Header:x-forwarded-proto---http
[2024-08-29 18:46:35.538][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Request Header:x-request-id---4cb99812-7eab-49d4-9812-b301d1b50b22
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: Http Response Headers:Rust Proxy Wasm......
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header::status---200
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:accept-ranges---bytes
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:cache-control---private, no-cache, no-store, proxy-revalidate, no-transform
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:connection---keep-alive
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:content-length---2443
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:content-type---text/html
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:date---Thu, 29 Aug 2024 10:46:35 GMT
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:etag---"58860410-98b"
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:last-modified---Mon, 23 Jan 2017 13:24:32 GMT
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:pragma---no-cache
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:server---bfe/1.0.8.18
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:set-cookie---BDORZ=27315; max-age=86400; domain=.baidu.com; path=/
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: HTTP Response Header:x-envoy-upstream-service-time---40
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: 获取响应的报文
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: 获取响应的报文
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: 获取响应的报文
[2024-08-29 18:46:35.579][354595][info][wasm] [source/extensions/common/wasm/context.cc:1195] wasm log http_body: response body:日志报文内容信息
[2024-08-29T10:46:35.538Z] "GET / HTTP/1.1" 200 - 0 2443 41 40 "-" "curl/8.5.0" "4cb99812-7eab-49d4-9812-b301d1b50b22" "www.baidu.com" "183.240.98.198:443"

When I use Istio's WasmPlugin, the log cannot appear, but the following code is executed.The response is:

{
    "....": "...",
    "headers": {
        "...": "...",
        "X-Rust-Liuxu-Trust": "proxy-wasm-rust"
    },
    "...": "..."
}

Did I do something wrong somewhere?

The relevant configuration of Istio is as follows:

Istio-version: v1.22.0 K8s: v1.26.3

---
apiVersion: telemetry.istio.io/v1
kind: Telemetry
metadata:
  name: mesh-default
  namespace: cpaas-dev
spec:
  selector:
    matchLabels:
      app: cpaas-convert
  accessLogging:
    - providers:
      - name: envoy
---
apiVersion: extensions.istio.io/v1alpha1
kind: WasmPlugin
metadata:
  name: http-body
  namespace: cpaas-dev
spec:
  imagePullPolicy: Always
  phase: STATS
  selector:
    matchLabels:
      app: cpaas-convert
  url: oci://xwharbor.wxchina.com/cpaas/wasm/envoy-plugin:v0.0.12

This is istio-proxy log:

2024-08-29T10:26:23.478580Z     info    wasm    fetching image cpaas/wasm/envoy-plugin from registry xwharbor.wxchina.com with tag v0.0.12
[2024-08-29T10:26:39.886Z] "POST /terminal/capability HTTP/1.1" 200 - via_upstream - "-" 147 114 18 16 "-" "Java/1.8.0_342" "bcb63487-09f7-4c64-9247-3f9d5ee2df86" "cpaas-biz-server-service:8080" "10.216.133.102:8080" outbound|8080||cpaas-biz-server-service.cpaas-dev.svc.idc.local 10.216.133.251:41324 10.218.137.248:8080 10.216.133.251:35950 - default
[2024-08-29T10:26:39.880Z] "POST /cpaas-convert/mobile/terminal/capability/106908061456@botplatform.rcs.chinamobile.com HTTP/1.1" 200 - via_upstream - "-" 49 49 26 24 "10.216.135.108" "k6/0.53.0 (https://k6.io/)" "ee5c4029-4e18-4315-beb1-8049ebfa941b" "10.20.121.49:30669" "10.216.133.251:8192" inbound|8192|| 127.0.0.6:41719 10.216.133.251:8192 10.216.135.108:0 - default
liuxuzxx commented 2 months ago 
fn on_http_response_headers(&mut self, _: usize, _: bool) -> Action {
        //No log output is seen for this line
        info!("Http Response Headers:Rust Proxy Wasm......");
        let headers = self.get_http_response_headers();
        for (name, value) in headers.iter() {
            info!("HTTP Response Header:{}---{}", name, value);
        }
        //But this line executes
        self.set_http_response_header("x-rust-liuxu-trust", Some("proxy-wasm-rust"));
        Action::Continue
    }
liuxuzxx commented 2 months ago

I known:

https://github.com/istio/istio/issues/44310