It's not possible to issue a second http call

[SvetlinZarev]

Hi,

Currently it's not possible to issue another http call from Context::on_http_call_response. Is this intentional ? If it is how is one supposed to make several http calls, for example fetch an oauth token, call another service with it, then resume the request ?

The error is:

[2020-10-25 11:04:04.792][12][critical][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1018] wasm log: panicked at 'already borrowed: BorrowMutError', /Users/svetlin/.cargo/registry/src/github.com-1ecc6299db9ec823/proxy-wasm-0.1.2/src/dispatcher.rs:137:14

I believe the error is caused because the dispatcher tries to borrow the callouts for a second time when registering the second http call.

The first borrow occurs when calling the on_http_call_response callback. The duration of the borrow lasts for the whole if let Some() body.

Given that the context_id is Copy, this method can be modified like that:

{
        let context_id = match self.callouts.borrow_mut().remove(&token_id) {
            Some(id) => id,
            None => panic!("invalid token_id")
        };

        if let Some(http_stream) = self.http_streams.borrow_mut().get_mut(&context_id) {
            self.active_id.set(context_id);
            hostcalls::set_effective_context(context_id).unwrap();
            http_stream.on_http_call_response(token_id, num_headers, body_size, num_trailers)
        } else if let Some(stream) = self.streams.borrow_mut().get_mut(&context_id) {
            self.active_id.set(context_id);
            hostcalls::set_effective_context(context_id).unwrap();
            stream.on_http_call_response(token_id, num_headers, body_size, num_trailers)
        } else if let Some(root) = self.roots.borrow_mut().get_mut(&context_id) {
            self.active_id.set(context_id);
            hostcalls::set_effective_context(context_id).unwrap();
            root.on_http_call_response(token_id, num_headers, body_size, num_trailers)
        }
    }

Thus eliminating the borrow on the callouts member, which resolves the issue.

What do you think ?

[SvetlinZarev]

Reproducible example:

Cargo.toml:

[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 = "0.1.2"
log = "0.4"

lib.rs:

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

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");

        log::info!("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::info!("> on_second");

        log::info!("Resuming original HTTP request...");
        self.resume_http_request();
        log::info!("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");
        log::error!("Call response headers: {:?}", self.get_http_call_response_headers());

        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::info!("> on_http_request_headers");

        log::info!("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
    }
}

envoy config:

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: "www.yandex.ru"
                route:
                  cluster: yandex
                  host_rewrite: www.yandex.ru
          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: yandex
    connect_timeout: 10s
    type: logical_dns
    dns_lookup_family: V4_ONLY
    lb_policy: round_robin
    load_assignment:
      cluster_name: yandex
      endpoints:
      - lb_endpoints:
        - endpoint:
            address:
              socket_address:
                address: www.yandex.ru
                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.yandex.ru
admin:
  access_log_path: "/dev/stdout"
  address:
    socket_address:
      address: 0.0.0.0
      port_value: 15000

Make an http request to the proxy:

 curl -vvv -w "\r\n" --header "Host: www.yandex.ru" localhost:15001

As a result envoy crashes due to multiple mutable borrows:

[2020-11-09 08:58:22.976][13][info][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1107] wasm log wasm_plugin : > on_http_request_headers
[2020-11-09 08:58:22.976][13][info][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1107] wasm log wasm_plugin : Dispatching HTTP request to cluster A...
[2020-11-09 08:58:22.977][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Call to cluster A dispatched
[2020-11-09 08:58:23.137][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : > on_http_call_response
[2020-11-09 08:58:23.138][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : Call response headers: [...]
[2020-11-09 08:58:23.138][13][error][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1113] wasm log wasm_plugin : > on_first
[2020-11-09 08:58:23.138][13][info][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1107] wasm log wasm_plugin : Dispatching HTTP request to cluster B...
[2020-11-09 08:58:23.139][13][critical][wasm] [external/envoy/source/extensions/common/wasm/context.cc:1116] wasm log wasm_plugin : panicked at 'already borrowed: BorrowMutError', /Users/svetlin/.cargo/registry/src/github.com-1ecc6299db9ec823/proxy-wasm-0.1.2/src/dispatcher.rs:137:14
[2020-11-09 08:58:23.151][13][critical][main] [external/envoy/source/exe/terminate_handler.cc:13] std::terminate called! (possible uncaught exception, see trace)
[2020-11-09 08:58:23.152][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:91] Backtrace (use tools/stack_decode.py to get line numbers):
[2020-11-09 08:58:23.152][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:92] Envoy version: 201124ab4fc06dc051c9aebdb49f1d2197e46f02/1.14.5-dev/Clean/RELEASE/BoringSSL
[2020-11-09 08:58:23.173][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #0: Envoy::TerminateHandler::logOnTerminate()::$_0::operator()() [0x55da91fd7814]
[2020-11-09 08:58:23.187][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:98] #1: [0x55da91fd7729]
[2020-11-09 08:58:23.201][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #2: std::__terminate() [0x55da9259d5a3]
[2020-11-09 08:58:23.215][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #3: std::__1::__function::__func<>::operator()() [0x55da90d9dffb]
[2020-11-09 08:58:23.229][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #4: Envoy::Extensions::Common::Wasm::Context::onHttpCallResponse() [0x55da90d627ea]
[2020-11-09 08:58:23.244][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #5: Envoy::Extensions::Common::Wasm::Context::onHttpCallSuccess() [0x55da90d64c62]
[2020-11-09 08:58:23.258][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #6: Envoy::Http::AsyncRequestImpl::onComplete() [0x55da91d0b17f]
[2020-11-09 08:58:23.272][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #7: Envoy::Http::AsyncStreamImpl::encodeData() [0x55da91d0ab33]
[2020-11-09 08:58:23.287][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #8: Envoy::Router::UpstreamRequest::decodeData() [0x55da91d1d2ae]
[2020-11-09 08:58:23.300][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #9: Envoy::Http::ResponseDecoderWrapper::decodeData() [0x55da91c89adb]
[2020-11-09 08:58:23.300][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #10: Envoy::Http::ResponseDecoderWrapper::decodeData() [0x55da91c89adb]
[2020-11-09 08:58:23.314][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #11: Envoy::Http::Http1::ClientConnectionImpl::onMessageComplete() [0x55da91d928a1]
[2020-11-09 08:58:23.328][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #12: Envoy::Http::Http1::ConnectionImpl::onMessageCompleteBase() [0x55da91d8feab]
[2020-11-09 08:58:23.342][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #13: Envoy::Http::Http1::ConnectionImpl::$_8::__invoke() [0x55da91d9461d]
[2020-11-09 08:58:23.356][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #14: http_parser_execute [0x55da91f5ea6c]
[2020-11-09 08:58:23.370][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #15: Envoy::Http::Http1::ConnectionImpl::dispatchSlice() [0x55da91d8f1da]
[2020-11-09 08:58:23.383][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #16: Envoy::Http::Http1::ConnectionImpl::dispatch() [0x55da91d8ef4f]
[2020-11-09 08:58:23.397][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #17: Envoy::Http::CodecClient::onData() [0x55da91cf9738]
[2020-11-09 08:58:23.411][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #18: Envoy::Http::CodecClient::CodecReadFilter::onData() [0x55da91cfa48d]
[2020-11-09 08:58:23.424][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #19: Envoy::Network::FilterManagerImpl::onContinueReading() [0x55da91b18d33]
[2020-11-09 08:58:23.439][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #20: Envoy::Network::ConnectionImpl::onReadReady() [0x55da91b14e75]
[2020-11-09 08:58:23.453][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #21: Envoy::Network::ConnectionImpl::onFileEvent() [0x55da91b141cd]
[2020-11-09 08:58:23.468][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #22: Envoy::Event::FileEventImpl::assignEvents()::$_0::__invoke() [0x55da91b0f1f6]
[2020-11-09 08:58:23.482][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #23: event_process_active_single_queue [0x55da91f5868b]
[2020-11-09 08:58:23.498][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #24: event_base_loop [0x55da91f56f1e]
[2020-11-09 08:58:23.513][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #25: Envoy::Server::WorkerImpl::threadRoutine() [0x55da91b03034]
[2020-11-09 08:58:23.528][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #26: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::$_0::__invoke() [0x55da9200d9e3]
[2020-11-09 08:58:23.528][13][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:96] #27: start_thread [0x7f83e33eafa3]

[PiotrSikora]

Thanks for the report and reproducer! I think your patch is correct. Could you send a PR?

[PiotrSikora]

Hi @SvetlinZarev, I see that you pushed fix to your fork (https://github.com/SvetlinZarev/proxy-wasm-rust-sdk/commit/5190a0437c9c96ec378839598793ea98fc6769e8), but you didn't open a PR. Could you do that or are you still working on it?

[SvetlinZarev]

Unfortunately I'm struggling with the OSS process at my place :( (due to the required CLA).

[PiotrSikora]

Do you have any ETA or is that unlikely to happen at all?