The on_http_call_response() callback is sporadically not invoked on requests containing a body

[SvetlinZarev]

Summary:

The on_http_call_response() callback is sporadically not invoked on requests containing a body. The issue is NOT reproducible on requests WITHOUT body.

MCVE

[package]
name = "wasm-mcve"
version = "0.1.0"
authors = ["Svetlin Zarev"]
edition = "2018"

[lib]
crate-type = ["cdylib"]

[profile.release]
opt-level = 2
lto = "fat"
codegen-units = 1

[dependencies]
proxy-wasm = { path = "/Users/svetlin/git/oss/proxy-wasm-rust-sdk" }
log = "0.4"

use std::time::Duration;
use proxy_wasm::traits::{Context, HttpContext};
use proxy_wasm::types::Action;

const HEADER_MARKER: &str = "x-wasm-marker";
const HEADER_CONNECTION: &str = "connection";
const HEADER_CONTENT_TYPE: &str = "content-type";
const HEADER_AUTHORITY: &str = ":authority";
const HEADER_HTTP_METHOD: &str = ":method";
const HEADER_PATH: &str = ":path";

const HTTP_METHOD_GET: &str = "GET";

const CONNECTION_CLOSE: &str = "close";
const CONTENT_TYPE_TEXT_PLAIN: &str = "text/plain";

const A_CLUSTER: &str = "google";
const A_AUTHORITY: &str = "www.google.com";

const B_CLUSTER: &str = "bing";
const B_AUTHORITY: &str = "www.bing.com";

const DEFAULT_TIMEOUT: Duration = Duration::from_secs(5);


#[no_mangle]
pub fn _start() {
    proxy_wasm::set_log_level(proxy_wasm::types::LogLevel::Trace);
    proxy_wasm::set_http_context(|_, _| Box::new(Plugin::new()));
}

#[derive(Debug, Copy, Clone, Eq, PartialEq)]
enum Response {
    None,
    First,
    Second,
}

struct Plugin {
    response: Response,
}

impl Plugin {
    fn new() -> Plugin {
        Plugin { response: Response::None }
    }

    #[inline]
    fn send_internal_server_error(&self) {
        log::error!("Sending internal server error...");
        self.send_http_response(
            500,
            vec![
                (HEADER_CONTENT_TYPE, CONTENT_TYPE_TEXT_PLAIN),
                (HEADER_CONNECTION, CONNECTION_CLOSE),
            ],
            Some("internal server error".as_bytes()),
        );
    }

    fn on_first(&mut self) {
        log::error!("> on_first");

        self.add_http_request_header(HEADER_MARKER, "on-first");

        log::error!("Dispatching HTTP request to cluster B...");
        let token = self.dispatch_http_call(
            B_CLUSTER,
            vec![
                (HEADER_AUTHORITY, B_AUTHORITY),
                (HEADER_HTTP_METHOD, HTTP_METHOD_GET),
                (HEADER_PATH, "/"),
            ], None,
            vec![],
            DEFAULT_TIMEOUT,
        );

        match token {
            Err(e) => {
                log::error!("Cannot dispatch call to cluster B: {:?}", e);
                self.send_internal_server_error();
            }

            Ok(_) => {
                log::error!("Call to cluster B dispatched");
                self.response = Response::Second;
            }
        }
    }

    fn on_second(&mut self) {
        log::error!("> on_second");

        self.add_http_request_header(HEADER_MARKER, "on-second");

        log::error!("Resuming original HTTP request...");
        self.resume_http_request();
        log::error!("Original HTTP request resumed");
    }
}

impl Context for Plugin {
    fn on_http_call_response(&mut self, _token_id: u32, _num_headers: usize, _body_size: usize, _num_trailers: usize) {
        log::error!("> on_http_call_response");

        let method = self.get_http_request_header(HEADER_HTTP_METHOD);
        let authority = self.get_http_request_header(HEADER_AUTHORITY);
        log::error!("Method: {:?}; Authority: {:?}", method, authority);

        let token = std::mem::replace(&mut self.response, Response::None);
        match token {
            Response::None => {
                log::error!("Unexpected http call response callback!");
                self.send_internal_server_error();
                return;
            }

            Response::First => {
                self.on_first();
            }

            Response::Second => {
                self.on_second()
            }
        }
    }
}

impl HttpContext for Plugin {
    fn on_http_request_headers(&mut self, _num_headers: usize) -> Action {
        log::error!("> on_http_request_headers");

        let method = self.get_http_request_header(HEADER_HTTP_METHOD);
        let authority = self.get_http_request_header(HEADER_AUTHORITY);
        log::error!("Method: {:?}; Authority: {:?}", method, authority);

        log::error!("Dispatching HTTP request to cluster A...");
        let token = self.dispatch_http_call(
            A_CLUSTER,
            vec![
                (HEADER_AUTHORITY, A_AUTHORITY),
                (HEADER_HTTP_METHOD, HTTP_METHOD_GET),
                (HEADER_PATH, "/"),
            ], None,
            vec![],
            DEFAULT_TIMEOUT,
        );

        match token {
            Err(e) => {
                log::error!("Cannot dispatch call to cluster A: {:?}", e);
                self.send_internal_server_error();
            }

            Ok(_) => {
                log::error!("Call to cluster A dispatched");
                self.response = Response::First;
            }
        }

        Action::Pause
    }
}

Sample envoy configuration (can be reproduced on istio as well)

static_resources:
  listeners:
  - address:
      socket_address:
        address: 0.0.0.0
        port_value: 15001
    filter_chains:
    - filters:
      - name: envoy.http_connection_manager 
        typed_config:
          "@type": type.googleapis.com/envoy.config.filter.network.http_connection_manager.v2.HttpConnectionManager
          codec_type: auto
          stat_prefix: http
          access_log:
            name: envoy.file_access_log
            typed_config:
              "@type": type.googleapis.com/envoy.config.accesslog.v2.FileAccessLog
              path: /dev/stdout
          route_config:
            name: search_route
            virtual_hosts:
            - name: backend
              domains:
              - "*"
              routes:
              - match:
                  prefix: "/"
                  headers:
                    - name: ":authority"
                      exact_match: "www.google.com"
                route:
                  cluster: google
                  host_rewrite: www.google.com
              - match:
                  prefix: "/"
                  headers:
                    - name: ":authority"
                      exact_match: "www.bing.com"
                route:
                  cluster: bing
                  host_rewrite: www.bing.com
              - match:
                  prefix: "/"
                  headers:
                    - name: ":authority"
                      exact_match: "requestbin"
                route:
                  cluster: requestbin
                  host_rewrite: f85bd0cbc72fec2729a2267267df5a57.m.pipedream.net
          http_filters:
          - name: envoy.filters.http.wasm
            typed_config:
              "@type": type.googleapis.com/envoy.extensions.filters.http.wasm.v3.Wasm
              config:
                name: "wasm_plugin"
                vmConfig:
                  runtime: "envoy.wasm.runtime.v8"
                  allowPrecompiled: true
                  code:
                    local:
                      filename: "/root/plugin.wasm"
                  allow_precompiled: true
          - name: envoy.filters.http.router
            typed_config: {}
  clusters:
  - name: google
    connect_timeout: 10s
    type: logical_dns
    dns_lookup_family: V4_ONLY
    lb_policy: round_robin
    load_assignment:
      cluster_name: google
      endpoints:
      - lb_endpoints:
        - endpoint:
            address:
              socket_address:
                address: www.google.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.google.com
  - name: bing
    connect_timeout: 10s
    type: logical_dns
    dns_lookup_family: V4_ONLY
    lb_policy: round_robin
    load_assignment:
      cluster_name: bing
      endpoints:
      - lb_endpoints:
        - endpoint:
            address:
              socket_address:
                address: www.bing.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.bing.com
  - name: requestbin
    connect_timeout: 10s
    type: logical_dns
    dns_lookup_family: V4_ONLY
    lb_policy: round_robin
    load_assignment:
      cluster_name: requestbin
      endpoints:
      - lb_endpoints:
        - endpoint:
            address:
              socket_address:
                address: f85bd0cbc72fec2729a2267267df5a57.m.pipedream.net
                port_value: 443
    transport_socket:
      name: envoy.transport_sockets.tls
      typed_config:
        "@type": type.googleapis.com/envoy.extensions.transport_sockets.tls.v3.UpstreamTlsContext
        sni: f85bd0cbc72fec2729a2267267df5a57.m.pipedream.net
admin:
  access_log_path: "/dev/stdout"
  address:
    socket_address:
      address: 0.0.0.0
      port_value: 15000

As the requestbin is not publicly visible you'll have to create your own and update the configuration accordingly.

Steps to reproduce

I'm reproducing it in a docker image (thus the localhost address), but can be done also on k8s with istio.

Make a POST request containing some body. It can be as simple as a single character

curl -kvvv -w "\r\n" -X POST  --header "Host: requestbin" localhost:15001 --data '{}'

Expectation

On envoy side

I expect to see in the logs that both of my callbacks have been invoked. Example:

[2020-11-19T18:52:05.366Z] "POST / HTTP/1.1" 200 - 2 19 200 199 "-" "curl/7.64.1" "ab455f56-392d-4983-bc16-df6534cdf0cc" "f85bd0cbc72fec2729a2267267df5a57.m.pipedream.net" "3.93.160.118:443"
[2020-11-19 19:03:06.526][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Borrowing streams: on_http_request_headers
[2020-11-19 19:03:06.527][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : > on_http_request_headers
[2020-11-19 19:03:06.527][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Method: Some("POST"); Authority: Some("requestbin")
[2020-11-19 19:03:06.527][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Dispatching HTTP request to cluster A...
[2020-11-19 19:03:06.527][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Call to cluster A dispatched
[2020-11-19 19:03:06.527][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Releasing streams: on_http_request_headers
[2020-11-19 19:03:06.727][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log : Borrowing streams: on_http_call_response
[2020-11-19 19:03:06.727][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : > on_http_call_response
[2020-11-19 19:03:06.727][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Method: Some("POST"); Authority: Some("requestbin")
[2020-11-19 19:03:06.727][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : > on_first
[2020-11-19 19:03:06.728][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Dispatching HTTP request to cluster B...
[2020-11-19 19:03:06.728][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Call to cluster B dispatched
[2020-11-19 19:03:06.728][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Releasing streams: on_http_call_response
[2020-11-19 19:03:07.104][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log : Borrowing streams: on_http_call_response
[2020-11-19 19:03:07.104][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : > on_http_call_response
[2020-11-19 19:03:07.104][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Method: Some("POST"); Authority: Some("requestbin")
[2020-11-19 19:03:07.104][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : > on_second
[2020-11-19 19:03:07.104][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Resuming original HTTP request...
[2020-11-19 19:03:07.105][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Original HTTP request resumed

On requestbin side

All of the x-wasm-marker header values are present. Example:

x-wasm-marker: on-first, on-second

What actually happens

On envoy side

Sometimes both callbacks are called, sometimes only the first one and sometimes no callback is invoked:

[2020-11-19T19:05:04.093Z] "POST / HTTP/1.1" 200 - 2 19 550 548 "-" "curl/7.64.1" "142a8042-8c26-4636-8697-7f3b843a5cd5" "f85bd0cbc72fec2729a2267267df5a57.m.pipedream.net" "34.197.21.136:443"
[2020-11-19 19:05:15.526][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Borrowing streams: on_http_request_headers
[2020-11-19 19:05:15.526][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : > on_http_request_headers
[2020-11-19 19:05:15.526][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Method: Some("POST"); Authority: Some("requestbin")
[2020-11-19 19:05:15.526][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Dispatching HTTP request to cluster A...
[2020-11-19 19:05:15.526][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Call to cluster A dispatched
[2020-11-19 19:05:15.526][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Releasing streams: on_http_request_headers
[2020-11-19 19:05:15.526][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Borrowing streams: on_http_request_body
[2020-11-19 19:05:15.526][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Releasing streams: on_http_request_body
[2020-11-19 19:05:15.526][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Borrowing streams: on_http_request_body
[2020-11-19 19:05:15.526][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Releasing streams: on_http_request_body
[2020-11-19 19:05:15.624][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log : Borrowing streams: on_http_call_response
[2020-11-19 19:05:15.624][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : > on_http_call_response
[2020-11-19 19:05:15.624][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Method: Some("POST"); Authority: Some("f85bd0cbc72fec2729a2267267df5a57.m.pipedream.net")
[2020-11-19 19:05:15.624][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : > on_first
[2020-11-19 19:05:15.624][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Dispatching HTTP request to cluster B...
[2020-11-19 19:05:15.624][12][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Call to cluster B dispatched

Note that we can see from the log that the second call was successfully dispatched, but the callback was never called.

On requestbin side

Some/All of the expected x-wasm-marker header values are missing

Without a request body

If you make the same request but without the body:

curl -kvvv -w "\r\n" -X POST  --header "Host: requestbin" localhost:15001 --data ''

The issue is NOT reproducible and works as expected 100% of the trials

[SvetlinZarev]

PS: In order to successfully reproduce the issue, either

• an SDK with fixed It's not possible to issue a second http call  #40 is required (otherwise it would not be possible to chain 2 http calls)
• or remove the second call from the MCVE (but you will have to run more trials, because the issue occurs sporadically)

[PiotrSikora]

Are you testing with latest Envoy? I think you might be hitting the same issue as we discussed in #43, i.e. request body is being processed even when headers are paused. This was fixed a few days ago in proxy-wasm/proxy-wasm-cpp-host#95 and envoyproxy/envoy#13840.

[SvetlinZarev]

You are right, this is a duplicate of #43. The issue is not reproducible on the latest envoy