From 6499d6d730d5c70dc76683b4837e267737c93fdd Mon Sep 17 00:00:00 2001 From: Thibault Charbonnier Date: Fri, 15 Nov 2024 08:48:28 -0800 Subject: [PATCH] feat(proxy-wasm) invoke 'on_http_call_response' on dispatch failures Invoke `on_http_call_response` on dispatch connection failures. This allows catching failures such as: - timeout - broken connection - resolver failures - TLS handshake failures - Any other failures *after the connection has attempted to be established* Dispatch failures occurring *before* a connection has attempted to be established will not trigger `on_http_call_response` as they are already supposed to trigger a Wasm exception (i.e. trap). When a dispatch connection failure occurs, `on_http_call_response` is invoked with: `on_http_call_response(call_id, 0, 0, 0)` (i.e. no header, no body, no trailers). Calls to retrieve the response `:status` will return `None`. A user may triage the connection failure by querying the `:dispatch_status` pseudo-header: ```rust fn on_http_call_response( &mut self, token_id: u32, nheaders: usize, body_size: usize, ntrailers: usize, ) { let dispatch_status = self.get_http_call_response_header(":dispatch_status"); match dispatch_status.as_deref() { Some("timeout") => {}, Some("broken connection") => {}, Some("tls handshake failure") => {}, Some("resolver failure") => {}, Some("reader failure") => {}, Some(s) => info!("dispatch_status: {}", s), None => {} } self.resume_http_request() } ``` The socket status `"bad argument"` also exists but since the connection has not been attempted yet, it won't show up during `on_http_call_response` and is for internal use only (i.e. could be added to the socket error log for example). Fix #622. --- docs/PROXY_WASM.md | 128 +++++++++++++++++- src/common/ngx_wasm_socket_tcp.c | 98 ++++++++++---- src/common/ngx_wasm_socket_tcp.h | 19 ++- src/common/proxy_wasm/ngx_proxy_wasm.c | 2 +- src/common/proxy_wasm/ngx_proxy_wasm_maps.c | 38 +++++- src/http/proxy_wasm/ngx_http_proxy_wasm.c | 40 +++--- .../proxy_wasm/ngx_http_proxy_wasm_dispatch.c | 105 ++++++++------ .../hfuncs/130-proxy_dispatch_http.t | 86 ++++++++++-- .../hfuncs/131-proxy_dispatch_http_timeouts.t | 30 +++- .../hfuncs/132-proxy_dispatch_http_ssl.t | 90 ++++++++++-- .../133-proxy_dispatch_http_edge_cases.t | 12 +- .../002-go_sdk/005-dispatch_call_on_tick.t | 2 + .../proxy-wasm-tests/hostcalls/src/filter.rs | 6 + util/sdks/go.sh | 11 ++ 14 files changed, 536 insertions(+), 131 deletions(-) diff --git a/docs/PROXY_WASM.md b/docs/PROXY_WASM.md index 0b98595e1..07568048f 100644 --- a/docs/PROXY_WASM.md +++ b/docs/PROXY_WASM.md @@ -10,6 +10,7 @@ - [Filters Execution in Nginx](#filters-execution-in-nginx) - [Host Properties] - [Nginx Properties] + - [HTTP Dispatches] - [Supported Specifications] - [Tested SDKs](#tested-sdks) - [Supported Entrypoints](#supported-entrypoints) @@ -107,13 +108,13 @@ proxy_wasm::main! {{ // the wasm instance initial entrypoint // ... proxy_wasm::set_log_level(LogLevel::Info); - // create and set the root context for this filter + // create and set the Root context for this filter proxy_wasm::set_root_context(|_| -> Box { Box::new(MyRootContext {}); }); }} -// implement root entrypoints +// implement Root entrypoints impl Context for TestRoot; impl RootContext for TestRoot { fn on_configure(&mut self, config_size: usize) -> bool { @@ -376,6 +377,120 @@ impl HttpContext for MyHttpContext { [Back to TOC](#table-of-contents) +### HTTP Dispatches + +Proxy-Wasm filters can issue requests to an external HTTP service. This feature +is called an "HTTP dispatch". + +In ngx_wasm_module, filters can issue a dispatch call with +`dispatch_http_call()` in the following steps: + +- `on_http_request_headers` +- `on_http_request_body` +- `on_tick` +- `on_http_call_response` (to issue subsequent calls) + +For example, in Rust: + +```rust +impl Context for ExampleHttpContext { + fn on_http_request_headers(&mut self, nheaders: usize, eof: bool) -> Action { + match self.dispatch_http_call( + "service.com", // host + vec![("X-Header", "Foo")], // headers + Some(b"hello world"), // body + vec![], // trailers + Duration::from_secs(3), // timeout + ) { + Ok(_) => info!("call scheduled"), + Err(status) => panic!("unexpected status \"{}\"", status as u32), + } + + Action::Pause + } +} +``` + +Several calls can be scheduled at the same time before returning +`Action::Pause`; they will be executed in parallel, their response handlers will +be invoked when each response is received, and the filter chain will resume once +all dispatch calls have finished executing. + +**Note:** in ngx_wasm_module, the `host` argument of a dispatch call must be a +valid IP address or a hostname which will be resolved using the [resolver] or +[proxy_wasm_lua_resolver] directives. This is unlike the Envoy implementation in +which the `host` argument receives a configured cluster name. + +Once the call is scheduled, the `on_http_call_response` handler will be invoked +when a response is received or the connection has encountered an error. If an +error was encountered while receiving the response, `on_http_call_response` is +invoked with its response arguments set to `0`. + +For example, in Rust: + +```rust +impl Context for ExampleHttpContext { + fn on_http_call_response( + &mut self, + token_id: u32, + nheaders: usize, + body_size: usize, + ntrailers: usize, + ) { + let status = self.get_http_call_response_header(":status"); + let body_bytes = self.get_http_call_response_body(0, body_size); + + if status.is_none() { + // Dispatch had an issue + // + // nheaders == 0 + // body_size == 0 + // ntrailers == 0 + + // ngx_wasm_module extension: retrieve error via :dispatch_status pseudo-header + let dispatch_status = self.get_http_call_response_header(":dispatch_status"); + match dispatch_status.as_deref() { + Some("timeout") => {}, + Some("broken connection") => {}, + Some("tls handshake failure") => {}, + Some("resolver failure") => {}, + Some("reader failure") => {}, + Some(s) => error!("dispatch failure, status: {}", s), + None => {} + } + } + + // ... + } +} +``` + +**Note:** if the dispatch call was invoked from the `on_tick` handler, +`on_http_call_response` must be implemented on the Root filter context instead +of the HTTP context: + +```rust +proxy_wasm::main! {{ + proxy_wasm::set_root_context(|_| -> Box { + Box::new(ExampleRootContext {}) + }); +}} + +impl Context for ExampleRootContext { + fn on_http_call_response( + &mut self, + token_id: u32, + nheaders: usize, + body_size: usize, + ntrailers: usize, + ) { + // Root context handler + } +} +``` + +[Back to TOC](#table-of-contents) + ## Supported Specifications This section describes the current state of support for the Proxy-Wasm @@ -429,7 +544,7 @@ SDK ABI `0.2.1`) and their present status in ngx_wasm_module: **Name** | **Supported** | **Comment** ----------------------------------:|:-------------------:|:-------------- *Root contexts* | | -`proxy_wasm::main!` | :heavy_check_mark: | Allocate the root context. +`proxy_wasm::main!` | :heavy_check_mark: | Allocate the Root context. `on_vm_start` | :heavy_check_mark: | VM configuration handler. `on_configure` | :heavy_check_mark: | Filter configuration handler. `on_tick` | :heavy_check_mark: | Background tick handler. @@ -636,7 +751,7 @@ implementation state in ngx_wasm_module: `source.port` | :heavy_check_mark: | :x: | Maps to [ngx.remote_port](https://nginx.org/en/docs/http/ngx_http_core_module.html#remote_port). *Proxy-Wasm properties* | | `plugin_name` | :heavy_check_mark: | :x: | Returns current filter name. -`plugin_root_id` | :heavy_check_mark: | :x: | Returns filter's root context id. +`plugin_root_id` | :heavy_check_mark: | :x: | Returns filter's Root context id. `plugin_vm_id` | :x: | :x: | *NYI*. `node` | :x: | :x: | Not supported. `cluster_name` | :x: | :x: | Not supported. @@ -743,7 +858,7 @@ payloads. 3. When making a dispatch call, a valid IP address or hostname must be given to `dispatch_http_call`. This is in contrast to Envoy's implementation in which - a configured cluster name must be given. + a configured cluster name must be given. See [HTTP Dispatches]. 4. The "queue" shared memory implementation does not implement an automatic eviction mechanism when the allocated memory slab is full: @@ -759,12 +874,15 @@ Proxy-Wasm SDK. [Filter Chains]: #filter-chains [Host Properties]: #host-properties [Nginx Properties]: #nginx-properties +[HTTP Dispatches]: #http-dispatches [Supported Specifications]: #supported-specifications [Supported Properties]: #supported-properties [Examples]: #examples [Current Limitations]: #current-limitations [wasm_response_body_buffers]: DIRECTIVES.md#wasm_response_body_buffers +[resolver]: DIRECTIVES.md#resolver +[proxy_wasm_lua_resolver]: DIRECTIVES.md#proxy_wasm_lua_resolver [WebAssembly]: https://webassembly.org/ [Nginx Variables]: https://nginx.org/en/docs/varindex.html diff --git a/src/common/ngx_wasm_socket_tcp.c b/src/common/ngx_wasm_socket_tcp.c index e39d2151e..e86f1d3b4 100644 --- a/src/common/ngx_wasm_socket_tcp.c +++ b/src/common/ngx_wasm_socket_tcp.c @@ -14,7 +14,7 @@ static void ngx_wasm_socket_tcp_err(ngx_wasm_socket_tcp_t *sock, - const char *fmt, ...); + ngx_wasm_socket_status_e status, const char *fmt, ...); static void ngx_wasm_socket_resolve_handler(ngx_resolver_ctx_t *ctx); static ngx_int_t ngx_wasm_socket_tcp_connect_peer(ngx_wasm_socket_tcp_t *sock); static ngx_int_t ngx_wasm_socket_tcp_get_peer(ngx_peer_connection_t *pc, @@ -36,14 +36,43 @@ static ngx_int_t ngx_wasm_socket_tcp_ssl_set_server_name(ngx_connection_t *c, #endif +static ngx_str_t ngx_wasm_socket_errlist[] = { + ngx_string("ok"), + ngx_string("bad argument"), + ngx_string("timeout"), + ngx_string("broken connection"), +#if (NGX_SSL) + ngx_string("tls handshake failure"), +#endif + ngx_string("resolver failure"), + ngx_string("reader failure"), + ngx_string("internal failure") +}; + + +ngx_str_t * +ngx_wasm_socket_tcp_status_strerror(ngx_wasm_socket_status_e status) +{ + ngx_str_t *msg; + + msg = ((ngx_uint_t) status < NGX_WASM_SOCKET_STATUS_INTERNAL_FAILURE) + ? &ngx_wasm_socket_errlist[status] + : &ngx_wasm_socket_errlist[NGX_WASM_SOCKET_STATUS_INTERNAL_FAILURE]; + + return msg; +} + + static void ngx_wasm_socket_tcp_err(ngx_wasm_socket_tcp_t *sock, + ngx_wasm_socket_status_e status, const char *fmt, ...) { va_list args; u_char *p, *last; if (sock->err == NULL) { + sock->status = status; sock->err = ngx_pnalloc(sock->pool, NGX_MAX_ERROR_STR); if (sock->err == NULL) { return; @@ -193,7 +222,8 @@ ngx_wasm_socket_tcp_init(ngx_wasm_socket_tcp_t *sock, sock->url.no_resolve = 1; if (ngx_parse_url(sock->pool, &sock->url) != NGX_OK) { - ngx_wasm_socket_tcp_err(sock, "%s", sock->url.err); + ngx_wasm_socket_tcp_err(sock, NGX_WASM_SOCKET_STATUS_BAD_ARGUMENT, + "%s", sock->url.err); return NGX_ERROR; } @@ -385,7 +415,8 @@ ngx_wasm_socket_tcp_connect(ngx_wasm_socket_tcp_t *sock) } if (rslv_ctx == NULL) { - ngx_wasm_socket_tcp_err(sock, "failed starting resolver"); + ngx_wasm_socket_tcp_err(sock, NGX_WASM_SOCKET_STATUS_INTERNAL_FAILURE, + "failed starting resolver"); return NGX_ERROR; } @@ -429,7 +460,9 @@ ngx_wasm_socket_resolve_handler(ngx_resolver_ctx_t *ctx) if (ctx->state || !ctx->naddrs) { #if (NGX_WASM_LUA) if (ctx->state == NGX_WASM_LUA_RESOLVE_ERR) { - ngx_wasm_socket_tcp_err(sock, "lua resolver failed"); + ngx_wasm_socket_tcp_err(sock, + NGX_WASM_SOCKET_STATUS_RESOLVER_FAILURE, + "lua resolver failed"); goto error; } #endif @@ -440,7 +473,8 @@ ngx_wasm_socket_resolve_handler(ngx_resolver_ctx_t *ctx) } #endif - ngx_wasm_socket_tcp_err(sock, "resolver error: %s", + ngx_wasm_socket_tcp_err(sock, NGX_WASM_SOCKET_STATUS_RESOLVER_FAILURE, + "resolver error: %s", ngx_resolver_strerror(ctx->state)); goto error; } @@ -571,12 +605,14 @@ ngx_wasm_socket_tcp_connect_peer(ngx_wasm_socket_tcp_t *sock) return NGX_ERROR; } else if (rc == NGX_BUSY) { - ngx_wasm_socket_tcp_err(sock, "no live connection"); + ngx_wasm_socket_tcp_err(sock, NGX_WASM_SOCKET_STATUS_INTERNAL_FAILURE, + "no live connection"); return NGX_BUSY; } else if (rc == NGX_DECLINED) { sock->socket_errno = ngx_socket_errno; - ngx_wasm_socket_tcp_err(sock, NULL); + ngx_wasm_socket_tcp_err(sock, NGX_WASM_SOCKET_STATUS_BROKEN_CONNECTION, + NULL); return NGX_ERROR; } @@ -686,11 +722,13 @@ ngx_wasm_socket_tcp_ssl_handshake_handler(ngx_connection_t *c) } if (c->write->timedout) { - ngx_wasm_socket_tcp_err(sock, "tls handshake timed out"); + ngx_wasm_socket_tcp_err(sock, NGX_WASM_SOCKET_STATUS_TLS_FAILURE, + "tls handshake timed out"); goto resume; } - ngx_wasm_socket_tcp_err(sock, "tls handshake failed"); + ngx_wasm_socket_tcp_err(sock, NGX_WASM_SOCKET_STATUS_TLS_FAILURE, + "tls handshake failed"); resume: @@ -722,6 +760,7 @@ ngx_wasm_socket_tcp_ssl_handshake_done(ngx_connection_t *c) rc = SSL_get_verify_result(c->ssl->connection); if (rc != X509_V_OK) { ngx_wasm_socket_tcp_err(sock, + NGX_WASM_SOCKET_STATUS_TLS_FAILURE, "tls certificate verify error: (%l:%s)", rc, X509_verify_cert_error_string(rc)); return NGX_ERROR; @@ -740,6 +779,7 @@ ngx_wasm_socket_tcp_ssl_handshake_done(ngx_connection_t *c) if (ngx_ssl_check_host(c, &sock->ssl_server_name) != NGX_OK) { ngx_wasm_socket_tcp_err(sock, + NGX_WASM_SOCKET_STATUS_TLS_FAILURE, "tls certificate CN " "does not match \"%V\" sni", &sock->ssl_server_name); @@ -809,6 +849,7 @@ ngx_wasm_socket_tcp_ssl_set_server_name(ngx_connection_t *c, || ngx_inet_addr(name->data, len) != INADDR_NONE) { ngx_wasm_socket_tcp_err(sock, + NGX_WASM_SOCKET_STATUS_TLS_FAILURE, "could not derive tls sni from host (\"%V\")", &sock->host); goto error; @@ -877,7 +918,8 @@ ngx_wasm_socket_tcp_send(ngx_wasm_socket_tcp_t *sock, ngx_chain_t *cl) ngx_connection_t *c; if (!sock->connected) { - ngx_wasm_socket_tcp_err(sock, "not connected"); + ngx_wasm_socket_tcp_err(sock, NGX_WASM_SOCKET_STATUS_INTERNAL_FAILURE, + "not connected"); return NGX_ERROR; } @@ -930,7 +972,8 @@ ngx_wasm_socket_tcp_send(ngx_wasm_socket_tcp_t *sock, ngx_chain_t *cl) if (n == NGX_ERROR) { c->error = 1; sock->socket_errno = ngx_socket_errno; - ngx_wasm_socket_tcp_err(sock, NULL); + ngx_wasm_socket_tcp_err(sock, NGX_WASM_SOCKET_STATUS_BROKEN_CONNECTION, + NULL); return NGX_ERROR; } @@ -1054,7 +1097,8 @@ ngx_wasm_socket_tcp_read(ngx_wasm_socket_tcp_t *sock, ngx_connection_t *c; if (!sock->connected) { - ngx_wasm_socket_tcp_err(sock, "not connected"); + ngx_wasm_socket_tcp_err(sock, NGX_WASM_SOCKET_STATUS_INTERNAL_FAILURE, + "not connected"); return NGX_ERROR; } @@ -1091,7 +1135,9 @@ ngx_wasm_socket_tcp_read(ngx_wasm_socket_tcp_t *sock, rc = reader(sock, size, reader_ctx); if (rc == NGX_ERROR) { - ngx_wasm_socket_tcp_err(sock, "parser error"); + ngx_wasm_socket_tcp_err(sock, + NGX_WASM_SOCKET_STATUS_READER_FAILURE, + "parser error"); return NGX_ERROR; } @@ -1159,7 +1205,9 @@ ngx_wasm_socket_tcp_read(ngx_wasm_socket_tcp_t *sock, if (n == NGX_ERROR) { sock->socket_errno = ngx_socket_errno; - ngx_wasm_socket_tcp_err(sock, NULL); + ngx_wasm_socket_tcp_err(sock, + NGX_WASM_SOCKET_STATUS_BROKEN_CONNECTION, + NULL); return NGX_ERROR; } @@ -1505,11 +1553,11 @@ ngx_wasm_socket_tcp_connect_handler(ngx_wasm_socket_tcp_t *sock) "wasm tcp socket timed out connecting to \"%V:%ud\"", &c->addr_text, ngx_inet_get_port(sock->peer.sockaddr)); - ngx_wasm_socket_tcp_err(sock, "timed out connecting to \"%V:%ud\"", + ngx_wasm_socket_tcp_err(sock, + NGX_WASM_SOCKET_STATUS_TIMEOUT, + "timed out connecting to \"%V:%ud\"", &c->addr_text, ngx_inet_get_port(sock->peer.sockaddr)); - - sock->timedout = 1; return; } @@ -1520,7 +1568,9 @@ ngx_wasm_socket_tcp_connect_handler(ngx_wasm_socket_tcp_t *sock) if (rc != NGX_OK) { if (rc > 0) { sock->socket_errno = (ngx_err_t) rc; - ngx_wasm_socket_tcp_err(sock, NULL); + ngx_wasm_socket_tcp_err(sock, + NGX_WASM_SOCKET_STATUS_BROKEN_CONNECTION, + NULL); } return; @@ -1560,11 +1610,11 @@ ngx_wasm_socket_tcp_send_handler(ngx_wasm_socket_tcp_t *sock) "wasm tcp socket timed out writing to \"%V:%ud\"", &c->addr_text, ngx_inet_get_port(sock->peer.sockaddr)); - ngx_wasm_socket_tcp_err(sock, "timed out writing to \"%V:%ud\"", + ngx_wasm_socket_tcp_err(sock, + NGX_WASM_SOCKET_STATUS_TIMEOUT, + "timed out writing to \"%V:%ud\"", &c->addr_text, ngx_inet_get_port(sock->peer.sockaddr)); - - sock->timedout = 1; return; } } @@ -1584,11 +1634,11 @@ ngx_wasm_socket_tcp_receive_handler(ngx_wasm_socket_tcp_t *sock) "wasm tcp socket timed out reading from \"%V:%ud\"", &c->addr_text, ngx_inet_get_port(sock->peer.sockaddr)); - ngx_wasm_socket_tcp_err(sock, "timed out reading from \"%V:%ud\"", + ngx_wasm_socket_tcp_err(sock, + NGX_WASM_SOCKET_STATUS_TIMEOUT, + "timed out reading from \"%V:%ud\"", &c->addr_text, ngx_inet_get_port(sock->peer.sockaddr)); - - sock->timedout = 1; return; } diff --git a/src/common/ngx_wasm_socket_tcp.h b/src/common/ngx_wasm_socket_tcp.h index af762efa7..f951f0541 100644 --- a/src/common/ngx_wasm_socket_tcp.h +++ b/src/common/ngx_wasm_socket_tcp.h @@ -18,6 +18,20 @@ typedef ngx_int_t (*ngx_wasm_socket_tcp_dns_resolver_pt)( ngx_resolver_ctx_t *rslv_ctx); +typedef enum { + NGX_WASM_SOCKET_STATUS_OK = 0, + NGX_WASM_SOCKET_STATUS_BAD_ARGUMENT, + NGX_WASM_SOCKET_STATUS_TIMEOUT, + NGX_WASM_SOCKET_STATUS_BROKEN_CONNECTION, +#if (NGX_SSL) + NGX_WASM_SOCKET_STATUS_TLS_FAILURE, +#endif + NGX_WASM_SOCKET_STATUS_RESOLVER_FAILURE, + NGX_WASM_SOCKET_STATUS_READER_FAILURE, + NGX_WASM_SOCKET_STATUS_INTERNAL_FAILURE, +} ngx_wasm_socket_status_e; + + typedef struct { ngx_str_t host; in_port_t port; @@ -39,6 +53,7 @@ struct ngx_wasm_socket_tcp_s { ngx_wasm_subsys_env_t *env; ngx_wasm_socket_tcp_resume_handler_pt resume_handler; + ngx_wasm_socket_status_e status; void *data; #if (NGX_WASM_LUA) ngx_wasm_lua_ctx_t *lctx; @@ -85,19 +100,19 @@ struct ngx_wasm_socket_tcp_s { /* flags */ - unsigned timedout:1; unsigned connected:1; unsigned eof:1; unsigned closed:1; unsigned read_closed:1; unsigned write_closed:1; - #if (NGX_SSL) unsigned ssl_ready:1; #endif }; +ngx_str_t *ngx_wasm_socket_tcp_status_strerror(ngx_wasm_socket_status_e status); + ngx_int_t ngx_wasm_socket_tcp_init(ngx_wasm_socket_tcp_t *sock, ngx_str_t *host, unsigned tls, ngx_str_t *sni, ngx_wasm_subsys_env_t *env); ngx_int_t ngx_wasm_socket_tcp_connect(ngx_wasm_socket_tcp_t *sock); diff --git a/src/common/proxy_wasm/ngx_proxy_wasm.c b/src/common/proxy_wasm/ngx_proxy_wasm.c index c2359216f..ce167ecba 100644 --- a/src/common/proxy_wasm/ngx_proxy_wasm.c +++ b/src/common/proxy_wasm/ngx_proxy_wasm.c @@ -852,7 +852,7 @@ ngx_proxy_wasm_run_step(ngx_proxy_wasm_exec_t *pwexec, } dd("<-- step rc: %ld, old_action: %d, ret action: %d, pwctx->action: %d, " - " ictx: %p", rc, old_action, action, pwctx->action, pwexec->ictx); + "ictx: %p", rc, old_action, action, pwctx->action, pwexec->ictx); /* pwctx->action writes in host calls overwrite action return value */ diff --git a/src/common/proxy_wasm/ngx_proxy_wasm_maps.c b/src/common/proxy_wasm/ngx_proxy_wasm_maps.c index 20c175bea..cab185b56 100644 --- a/src/common/proxy_wasm/ngx_proxy_wasm_maps.c +++ b/src/common/proxy_wasm/ngx_proxy_wasm_maps.c @@ -35,6 +35,8 @@ static ngx_str_t *ngx_proxy_wasm_maps_get_response_status( static ngx_int_t ngx_proxy_wasm_maps_set_response_status( ngx_wavm_instance_t *instance, ngx_str_t *value, ngx_proxy_wasm_map_type_e map_type); +static ngx_str_t *ngx_proxy_wasm_maps_get_dispatch_response_status( + ngx_wavm_instance_t *instance, ngx_proxy_wasm_map_type_e map_type); static ngx_str_t *ngx_proxy_wasm_maps_get_dispatch_status( ngx_wavm_instance_t *instance, ngx_proxy_wasm_map_type_e map_type); #endif @@ -75,6 +77,11 @@ static ngx_proxy_wasm_maps_key_t ngx_proxy_wasm_maps_special_keys[] = { /* dispatch response */ { ngx_string(":status"), + NGX_PROXY_WASM_MAP_HTTP_CALL_RESPONSE_HEADERS, + ngx_proxy_wasm_maps_get_dispatch_response_status, + NULL }, + + { ngx_string(":dispatch_status"), NGX_PROXY_WASM_MAP_HTTP_CALL_RESPONSE_HEADERS, ngx_proxy_wasm_maps_get_dispatch_status, NULL }, @@ -118,8 +125,14 @@ ngx_proxy_wasm_maps_get_map(ngx_wavm_instance_t *instance, } reader = &call->http_reader; + r = &reader->fake_r; + + if (!r->signature) { + /* reader not initialized */ + return NULL; + } - return &reader->fake_r.upstream->headers_in.headers; + return &r->upstream->headers_in.headers; #endif default: @@ -753,7 +766,7 @@ ngx_proxy_wasm_maps_set_response_status(ngx_wavm_instance_t *instance, static ngx_str_t * -ngx_proxy_wasm_maps_get_dispatch_status(ngx_wavm_instance_t *instance, +ngx_proxy_wasm_maps_get_dispatch_response_status(ngx_wavm_instance_t *instance, ngx_proxy_wasm_map_type_e map_type) { ngx_uint_t status; @@ -771,9 +784,8 @@ ngx_proxy_wasm_maps_get_dispatch_status(ngx_wavm_instance_t *instance, /* status */ - ngx_wa_assert(reader->fake_r.upstream); - if (reader->fake_r.upstream == NULL) { + /* response not received */ return NULL; } @@ -810,4 +822,22 @@ ngx_proxy_wasm_maps_get_dispatch_status(ngx_wavm_instance_t *instance, return &pwctx->call_status; } + + +static ngx_str_t * +ngx_proxy_wasm_maps_get_dispatch_status(ngx_wavm_instance_t *instance, + ngx_proxy_wasm_map_type_e map_type) +{ + ngx_proxy_wasm_exec_t *pwexec; + ngx_http_proxy_wasm_dispatch_t *call; + ngx_wasm_socket_tcp_t *sock; + + ngx_wa_assert(map_type == NGX_PROXY_WASM_MAP_HTTP_CALL_RESPONSE_HEADERS); + + pwexec = ngx_proxy_wasm_instance2pwexec(instance); + call = pwexec->call; + sock = &call->sock; + + return ngx_wasm_socket_tcp_status_strerror(sock->status); +} #endif diff --git a/src/http/proxy_wasm/ngx_http_proxy_wasm.c b/src/http/proxy_wasm/ngx_http_proxy_wasm.c index d8f809116..463aea2b7 100644 --- a/src/http/proxy_wasm/ngx_http_proxy_wasm.c +++ b/src/http/proxy_wasm/ngx_http_proxy_wasm.c @@ -313,39 +313,45 @@ ngx_http_proxy_wasm_on_dispatch_response(ngx_proxy_wasm_exec_t *pwexec) { size_t i; ngx_int_t rc; - ngx_uint_t n_headers; + ngx_uint_t n_headers, body_len; ngx_list_part_t *part; ngx_proxy_wasm_filter_t *filter = pwexec->filter; ngx_http_proxy_wasm_dispatch_t *call = pwexec->call; ngx_http_wasm_req_ctx_t *rctx = call->rctx; - part = &call->http_reader.fake_r.upstream->headers_in.headers.part; + n_headers = 0; + body_len = 0; - for (i = 0, n_headers = 0; /* void */; i++, n_headers++) { - if (i >= part->nelts) { - if (part->next == NULL) { - break; - } + if (call->http_reader.fake_r.signature) { + /* reader initialized */ + part = &call->http_reader.fake_r.upstream->headers_in.headers.part; + + for (i = 0, n_headers = 0; /* void */; i++, n_headers++) { + if (i >= part->nelts) { + if (part->next == NULL) { + break; + } - part = part->next; - i = 0; + part = part->next; + i = 0; + } } - /* void */ - } + body_len = call->http_reader.body_len; - ngx_log_debug3(NGX_LOG_DEBUG_ALL, pwexec->log, 0, - "proxy_wasm http dispatch response received " - "(pwexec->id: %d, token_id: %d, n_headers: %d)", - pwexec->id, call->id, n_headers); + ngx_log_debug4(NGX_LOG_DEBUG_ALL, pwexec->log, 0, + "proxy_wasm http dispatch response received " + "(pwexec->id: %d, token_id: %d, n_headers: %d, " + "body_len: %d)", pwexec->id, call->id, n_headers, + body_len); + } ngx_wasm_continue(&rctx->env); rc = ngx_wavm_instance_call_funcref(pwexec->ictx->instance, filter->proxy_on_http_call_response, NULL, filter->id, call->id, - n_headers, - call->http_reader.body_len, 0); /* eof: 0 */ + n_headers, body_len, 0); /* eof: 0 */ return rc; } diff --git a/src/http/proxy_wasm/ngx_http_proxy_wasm_dispatch.c b/src/http/proxy_wasm/ngx_http_proxy_wasm_dispatch.c index bfe15af25..4812cd1b2 100644 --- a/src/http/proxy_wasm/ngx_http_proxy_wasm_dispatch.c +++ b/src/http/proxy_wasm/ngx_http_proxy_wasm_dispatch.c @@ -10,7 +10,7 @@ static ngx_str_t *ngx_http_proxy_wasm_dispatch_strerror( ngx_http_proxy_wasm_dispatch_err_e err); static void ngx_http_proxy_wasm_dispatch_err( - ngx_http_proxy_wasm_dispatch_t *call); + ngx_http_proxy_wasm_dispatch_t *call, unsigned resume); static void ngx_http_proxy_wasm_dispatch_handler(ngx_event_t *ev); static ngx_chain_t *ngx_http_proxy_wasm_dispatch_request( ngx_http_proxy_wasm_dispatch_t *call); @@ -52,8 +52,55 @@ ngx_http_proxy_wasm_dispatch_strerror(ngx_http_proxy_wasm_dispatch_err_e err) } +static ngx_int_t +invoke_on_http_dispatch_response(ngx_proxy_wasm_exec_t *pwexec, + ngx_http_proxy_wasm_dispatch_t *call) +{ + ngx_proxy_wasm_step_e step; + ngx_proxy_wasm_err_e ecode; + + /** + * Set current call for subsequent call detection after the step + * (no yielding). + */ + pwexec->call = call; + + /** + * Save step: ngx_proxy_wasm_run_step will set pwctx->step (for host + * calls that need it), but we want to resume to the current step when + * all calls are finished (i.e. on_request_headers), so we'll save it + * here and set it back after run_step. + * + * This could eventually move to ngx_proxy_wasm_run_step if needed for + * other "single step invocations". + */ + step = pwexec->parent->step; + +#ifdef NGX_WASM_HTTP + pwexec->parent->phase = ngx_wasm_phase_lookup(&ngx_http_wasm_subsystem, + NGX_WASM_BACKGROUND_PHASE); +#endif + + ecode = ngx_proxy_wasm_run_step(pwexec, + NGX_PROXY_WASM_STEP_DISPATCH_RESPONSE); + if (ecode != NGX_PROXY_WASM_ERR_NONE) { + /* catch trap for tcp socket resume retval */ + return NGX_ERROR; + } + + /* reset step */ + pwexec->parent->step = step; + + /* remove current call now that callback was invoked */ + pwexec->call = NULL; + + return NGX_OK; +} + + static void -ngx_http_proxy_wasm_dispatch_err(ngx_http_proxy_wasm_dispatch_t *call) +ngx_http_proxy_wasm_dispatch_err(ngx_http_proxy_wasm_dispatch_t *call, + unsigned resume) { #if 0 const char *fmt, ...) @@ -77,6 +124,8 @@ ngx_http_proxy_wasm_dispatch_err(ngx_http_proxy_wasm_dispatch_t *call) p = ngx_slprintf(p, last, "dispatch failed"); if (sock->errlen) { + ngx_wa_assert(sock->status != NGX_WASM_SOCKET_STATUS_OK); + p = ngx_slprintf(p, last, ": %*s", (int) sock->errlen, sock->err); } @@ -104,6 +153,10 @@ ngx_http_proxy_wasm_dispatch_err(ngx_http_proxy_wasm_dispatch_t *call) p - (u_char *) &errbuf, &errbuf); } + if (resume) { + (void) invoke_on_http_dispatch_response(pwexec, call); + } + ngx_http_proxy_wasm_dispatch_destroy(call); pwexec->call = NULL; @@ -410,7 +463,7 @@ ngx_http_proxy_wasm_dispatch(ngx_proxy_wasm_exec_t *pwexec, error: if (call) { - ngx_http_proxy_wasm_dispatch_err(call); + ngx_http_proxy_wasm_dispatch_err(call, 0); } return NULL; @@ -718,8 +771,6 @@ ngx_http_proxy_wasm_dispatch_resume_handler(ngx_wasm_socket_tcp_t *sock) ngx_http_request_t *r = rctx->r; ngx_proxy_wasm_exec_t *pwexec = call->pwexec; ngx_proxy_wasm_filter_t *filter = pwexec->filter; - ngx_proxy_wasm_err_e ecode = NGX_PROXY_WASM_ERR_NONE; - ngx_proxy_wasm_step_e step = pwexec->parent->step; dd("enter"); @@ -830,42 +881,12 @@ ngx_http_proxy_wasm_dispatch_resume_handler(ngx_wasm_socket_tcp_t *sock) /* call has finished */ ngx_queue_remove(&call->q); - /** - * Set current call for subsequent call detection after the step - * (no yielding). - */ - pwexec->call = call; - - /** - * Save step: ngx_proxy_wasm_run_step will set pwctx->step (for host - * calls that need it), but we want to resume to the current step when - * all calls are finished (i.e. on_request_headers), so we'll save it - * here and set it back after run_step. - * - * This could eventually move to ngx_proxy_wasm_run_step if needed for - * other "single step invocations". - */ - step = pwexec->parent->step; - -#ifdef NGX_WASM_HTTP - pwexec->parent->phase = ngx_wasm_phase_lookup(&ngx_http_wasm_subsystem, - NGX_WASM_BACKGROUND_PHASE); -#endif - - ecode = ngx_proxy_wasm_run_step(pwexec, - NGX_PROXY_WASM_STEP_DISPATCH_RESPONSE); - if (ecode != NGX_PROXY_WASM_ERR_NONE) { - /* catch trap for tcp socket resume retval */ + if (invoke_on_http_dispatch_response(pwexec, call) != NGX_OK) { rc = NGX_ERROR; - goto error2; + ngx_http_proxy_wasm_dispatch_err(call, 0); + goto done; } - /* reset step */ - pwexec->parent->step = step; - - /* remove current call now that callback was invoked */ - pwexec->call = NULL; - ngx_http_proxy_wasm_dispatch_destroy(call); break; @@ -887,15 +908,13 @@ ngx_http_proxy_wasm_dispatch_resume_handler(ngx_wasm_socket_tcp_t *sock) error2: - if (ecode != NGX_PROXY_WASM_ERR_NONE - || rc == NGX_ABORT) - { + if (rc == NGX_ABORT) { /* catch trap for tcp socket resume retval or an instance * that trapped before the response was received */ rc = NGX_ERROR; } - ngx_http_proxy_wasm_dispatch_err(call); + ngx_http_proxy_wasm_dispatch_err(call, 1); done: @@ -920,7 +939,7 @@ ngx_http_proxy_wasm_dispatch_resume_handler(ngx_wasm_socket_tcp_t *sock) if (rc != NGX_ERROR) { rc = ngx_proxy_wasm_resume(pwexec->parent, pwexec->parent->phase, - step); + pwexec->parent->step); } } diff --git a/t/03-proxy_wasm/hfuncs/130-proxy_dispatch_http.t b/t/03-proxy_wasm/hfuncs/130-proxy_dispatch_http.t index 7356cd8a7..864deb80d 100644 --- a/t/03-proxy_wasm/hfuncs/130-proxy_dispatch_http.t +++ b/t/03-proxy_wasm/hfuncs/130-proxy_dispatch_http.t @@ -7,7 +7,7 @@ use t::TestWasmX; our $ExtResolver = $t::TestWasmX::extresolver; our $ExtTimeout = $t::TestWasmX::exttimeout; -plan_tests(4); +plan_tests(5); run_tests(); __DATA__ @@ -24,6 +24,7 @@ __DATA__ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - no host/ --- no_error_log [crit] +on_http_call_response @@ -40,6 +41,7 @@ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - no host qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - no host/ --- no_error_log [crit] +on_http_call_response @@ -56,6 +58,7 @@ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - no host qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - invalid port/ --- no_error_log [crit] +on_http_call_response @@ -72,6 +75,7 @@ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - invalid qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - invalid host/ --- no_error_log [crit] +on_http_call_response @@ -88,6 +92,7 @@ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - invalid qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - invalid port/ --- no_error_log [crit] +on_http_call_response @@ -105,6 +110,7 @@ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - invalid qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: no :method/ --- no_error_log [crit] +on_http_call_response @@ -123,6 +129,7 @@ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: no :method/ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: no :method/ --- no_error_log [crit] +on_http_call_response @@ -140,6 +147,7 @@ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: no :method/ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: no :path/ --- no_error_log [crit] +on_http_call_response @@ -155,7 +163,10 @@ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: no :path/ --- response_body ok --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - Connection refused/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - Connection refused/, + "dispatch_status: broken connection" +] --- no_error_log [crit] @@ -174,7 +185,10 @@ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - Connect --- error_code: 500 --- response_body_like: 500 Internal Server Error --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: no resolver defined to resolve "localhost"/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: no resolver defined to resolve "localhost"/, + "dispatch_status: resolver failure" +] --- no_error_log [crit] @@ -196,6 +210,8 @@ qq{ qr/\[error\]/, qr/dispatch failed: tcp socket - no path in the unix domain socket/ ] +--- no_error_log +on_http_call_response @@ -214,7 +230,8 @@ qq{ --- error_log eval [ qr/\[crit\] .*? connect\(\) to unix:\/tmp\/inexistent_file\.sock failed .*? No such file or directory/, - qr/\[error\] .*? dispatch failed: tcp socket - No such file or directory/ + qr/\[error\] .*? dispatch failed: tcp socket - No such file or directory/, + "dispatch_status: broken connection" ] @@ -236,7 +253,8 @@ qq{ --- error_log eval [ qr/\[(error|crit)\] .*? connect\(\) to unix:\/tmp failed .*? (Connection refused|Socket operation on non-socket)/, - qr/\[error\] .*? dispatch failed: tcp socket - (Connection refused|Socket operation on non-socket)/ + qr/\[error\] .*? dispatch failed: tcp socket - (Connection refused|Socket operation on non-socket)/, + "dispatch_status: broken connection" ] @@ -257,11 +275,13 @@ qq{ qr/\[error\]/, qr/dispatch failed: tcp socket - invalid host/ ] +--- no_error_log +on_http_call_response === TEST 15: proxy_wasm - dispatch_http_call() sanity (default resolver) ---- skip_eval: 4: defined $ENV{GITHUB_ACTIONS} +--- skip_eval: 5: defined $ENV{GITHUB_ACTIONS} --- timeout eval: $::ExtTimeout --- load_nginx_modules: ngx_http_echo_module --- main_config eval @@ -282,6 +302,7 @@ ok --- no_error_log [error] [crit] +[alert] @@ -309,6 +330,7 @@ ok --- no_error_log [error] [crit] +[alert] @@ -337,6 +359,7 @@ Hello back --- no_error_log [error] [crit] +[alert] @@ -375,6 +398,7 @@ Host: localhost\s* --- no_error_log [error] [crit] +[alert] @@ -385,7 +409,7 @@ Succeeds on: - HTTP 200 (httpbin.org/headers success) - HTTP 502 (httpbin.org Bad Gateway) - HTTP 504 (httpbin.org Gateway timeout) ---- skip_eval: 4: $::osname =~ m/darwin/ +--- skip_eval: 5: $::osname =~ m/darwin/ --- valgrind --- timeout eval: $::ExtTimeout --- load_nginx_modules: ngx_http_echo_module @@ -412,12 +436,13 @@ qq{ --- no_error_log [error] [crit] +[alert] === TEST 20: proxy_wasm - dispatch_http_call() sanity resolver + hostname (IPv6), default port Disabled on GitHub Actions due to IPv6 constraint. ---- skip_eval: 4: system("ping6 -c 1 ::1 >/dev/null 2>&1") ne 0 || defined $ENV{GITHUB_ACTIONS} +--- skip_eval: 5: system("ping6 -c 1 ::1 >/dev/null 2>&1") ne 0 || defined $ENV{GITHUB_ACTIONS} --- timeout eval: $::ExtTimeout --- load_nginx_modules: ngx_http_echo_module --- wasm_modules: hostcalls @@ -439,6 +464,7 @@ qq{ --- no_error_log [error] [crit] +[alert] @@ -476,6 +502,7 @@ qq{ --- no_error_log [error] [crit] +[alert] @@ -498,7 +525,10 @@ qq{ --- response_body ok --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - resolver error: Host not found/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - resolver error: Host not found/, + "dispatch_status: resolver failure" +] --- no_error_log [crit] @@ -524,6 +554,7 @@ ok --- no_error_log [error] [crit] +[alert] @@ -550,6 +581,7 @@ ok --- no_error_log [error] [crit] +[alert] @@ -584,6 +616,7 @@ qq{ --- no_error_log [error] [crit] +[alert] @@ -622,6 +655,7 @@ qq{ --- no_error_log [error] [crit] +[alert] @@ -660,6 +694,7 @@ K: 11.* --- no_error_log [error] [crit] +[alert] @@ -689,6 +724,7 @@ tcp socket reading done tcp socket closing --- no_error_log [error] +[crit] @@ -717,6 +753,7 @@ tcp socket reading done tcp socket closing --- no_error_log [error] +[crit] @@ -747,6 +784,7 @@ tcp socket reading done tcp socket closing --- no_error_log [error] +[crit] @@ -770,6 +808,7 @@ Hello world --- no_error_log [error] [crit] +[alert] @@ -795,6 +834,7 @@ Content-Length: 0.* --- no_error_log [error] [crit] +[alert] @@ -822,6 +862,7 @@ Content-Length: 0.* --- no_error_log [error] [crit] +[alert] @@ -851,6 +892,7 @@ Hello world tcp socket trying to receive data (max: 1) --- no_error_log [error] +[crit] @@ -879,6 +921,7 @@ Hello world --- no_error_log [error] [crit] +[alert] @@ -907,6 +950,7 @@ Hello world tcp socket trying to receive data (max: 1) tcp socket trying to receive data (max: 11) tcp socket - upstream response headers too large, increase wasm_socket_large_buffers size +dispatch_status: reader failure @@ -935,6 +979,7 @@ tcp socket - upstream response headers too large, increase wasm_socket_large_buf tcp socket trying to receive data (max: 24) tcp socket trying to receive data (max: 5) tcp socket - upstream response headers too large, increase wasm_socket_large_buffers size +dispatch_status: reader failure @@ -965,7 +1010,8 @@ ok --- error_log eval [ qr/tcp socket - not enough large buffers available, increase wasm_socket_large_buffers number/, - qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - parser error/ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - parser error/, + "dispatch_status: reader failure" ] @@ -996,6 +1042,7 @@ Hello world --- error_log tcp socket trying to receive data (max: 1) tcp socket trying to receive data (max: 1023) +on_http_call_response @@ -1018,7 +1065,10 @@ sub { --- response_body ok --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - parser error/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - parser error/, + "dispatch_status: reader failure" +] --- no_error_log [crit] @@ -1049,6 +1099,7 @@ Hello world --- error_log tcp socket trying to receive data (max: 24) tcp socket trying to receive data (max: 1017) +on_http_call_response @@ -1072,6 +1123,7 @@ tcp socket trying to receive data (max: 1017) ok --- error_log eval [ + "on_http_call_response", qr/\[crit\] .*? panicked at/, qr/trap!/, ] @@ -1098,7 +1150,10 @@ sub { --- response_body ok --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - parser error/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - parser error/, + "dispatch_status: reader failure" +] --- no_error_log [crit] @@ -1149,6 +1204,7 @@ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - parser --- no_error_log [error] [crit] +[alert] @@ -1183,6 +1239,7 @@ qr/^\*\d+ .*? on_http_call_response \(id: \d+[^*]* --- no_error_log [error] [crit] +[alert] @@ -1208,6 +1265,7 @@ X-Callout-Header: callout-header-value --- no_error_log [error] [crit] +[alert] @@ -1251,6 +1309,7 @@ qr/^\*\d+ .*? on_http_call_response \(id: \d+, status: 200[^*]* --- no_error_log [error] [crit] +[alert] @@ -1278,6 +1337,7 @@ helloworld --- no_error_log [error] [crit] +[alert] @@ -1305,6 +1365,7 @@ helloworl --- no_error_log [error] [crit] +[alert] @@ -1329,3 +1390,4 @@ cannot override the "Host" header, skipping cannot override the "Connection" header, skipping --- no_error_log [error] +[crit] diff --git a/t/03-proxy_wasm/hfuncs/131-proxy_dispatch_http_timeouts.t b/t/03-proxy_wasm/hfuncs/131-proxy_dispatch_http_timeouts.t index 8ea0def08..5d875d350 100644 --- a/t/03-proxy_wasm/hfuncs/131-proxy_dispatch_http_timeouts.t +++ b/t/03-proxy_wasm/hfuncs/131-proxy_dispatch_http_timeouts.t @@ -14,7 +14,7 @@ use t::TestWasmX; our $ExtResolver = $t::TestWasmX::extresolver; our $ExtTimeout = $t::TestWasmX::exttimeout; -plan_tests(4); +plan_tests(6); run_tests(); __DATA__ @@ -39,7 +39,11 @@ qq{ --- response_body ok --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - timed out connecting to \".*?\"/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - timed out connecting to \".*?\"/, + qr/\*\d+ .*? on_http_call_response \(id: \d+, status: , headers: 0, body_bytes: 0/, + qr/dispatch_status: timeout/ +] --- no_error_log [crit] @@ -65,7 +69,11 @@ qq{ --- response_body ok --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - resolver error: Operation timed out/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - resolver error: Operation timed out/, + qr/on_http_call_response \(id: \d+, status: , headers: 0, body_bytes: 0/, + "dispatch_status: resolver failure" +] --- no_error_log [crit] @@ -92,7 +100,11 @@ macOS: mockeagain NYI --- response_body ok --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - timed out reading from \"127\.0\.0\.1:\d+\"/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - timed out reading from \"127\.0\.0\.1:\d+\"/, + qr/on_http_call_response \(id: \d+, status: (\d+)?, headers: \d+, body_bytes: \d+/, + "dispatch_status: timeout" +] --- no_error_log [crit] @@ -121,7 +133,11 @@ macOS: mockeagain NYI --- response_body ok --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - timed out writing to \".*?\"/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - timed out writing to \".*?\"/, + qr/on_http_call_response \(id: \d+, status: , headers: 0, body_bytes: 0/, + "dispatch_status: timeout" +] --- no_error_log [crit] @@ -149,6 +165,8 @@ Hello world --- no_error_log [error] [crit] +[alert] +[emerg] @@ -179,3 +197,5 @@ Hello world --- no_error_log [error] [crit] +[alert] +[emerg] diff --git a/t/03-proxy_wasm/hfuncs/132-proxy_dispatch_http_ssl.t b/t/03-proxy_wasm/hfuncs/132-proxy_dispatch_http_ssl.t index 7b8ca5bdb..9228315b6 100644 --- a/t/03-proxy_wasm/hfuncs/132-proxy_dispatch_http_ssl.t +++ b/t/03-proxy_wasm/hfuncs/132-proxy_dispatch_http_ssl.t @@ -17,7 +17,7 @@ add_block_preprocessor(sub { } }); -plan_tests(4); +plan_tests(6); run_tests(); __DATA__ @@ -54,6 +54,9 @@ ok qr/\[warn\] .*? tls certificate not verified/, qr/\[warn\] .*? tls certificate host not verified/ ] +--- no_error_log +[error] +[crit] @@ -93,7 +96,9 @@ ok --- no_error_log eval [ qr/tls certificate not verified/, - qr/\[error\]/ + "[error]", + "[crit]", + "[alert]" ] @@ -138,6 +143,8 @@ Content-Length: 0.* qr/verifying tls certificate for "hostname:\d+" \(sni: "hostname"\)/ --- no_error_log [error] +[crit] +[alert] @@ -185,6 +192,8 @@ Content-Length: 0.* "verifying tls certificate for \"unix:$ENV{TEST_NGINX_UNIX_SOCKET}\" (sni: \"localhost\")" --- no_error_log [error] +[crit] +[alert] @@ -213,7 +222,11 @@ qq{ --- response_body ok --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - tls certificate verify error: \(10:certificate has expired\)/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - tls certificate verify error: \(10:certificate has expired\)/, + qr/\*\d+ .*? on_http_call_response \(id: \d+, status: , headers: 0, body_bytes: 0/, + qr/dispatch_status: tls handshake failure/ +] --- no_error_log [crit] @@ -260,6 +273,8 @@ Content-Length: 0.* qr/checking tls certificate CN for "hostname:\d+" \(sni: "hostname"\)/ --- no_error_log [error] +[crit] +[alert] @@ -294,7 +309,11 @@ qq{ --- response_body ok --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - tls certificate CN does not match \"localhost\" sni/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - tls certificate CN does not match \"localhost\" sni/, + qr/\*\d+ .*? on_http_call_response \(id: \d+, status: , headers: 0, body_bytes: 0/, + qr/dispatch_status: tls handshake failure/ +] --- no_error_log [crit] @@ -325,7 +344,11 @@ qq{ --- response_body ok --- error_log eval -qr/tls certificate verify error: \(19:self.signed certificate in certificate chain\)/ +[ + qr/tls certificate verify error: \(19:self.signed certificate in certificate chain\)/, + qr/\*\d+ .*? on_http_call_response \(id: \d+, status: , headers: 0, body_bytes: 0/, + qr/dispatch_status: tls handshake failure/ +] --- no_error_log [crit] @@ -353,7 +376,9 @@ ok --- error_log eval [ qr/\[crit\] .*? SSL_do_handshake\(\) failed/, - qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - tls handshake failed/ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - tls handshake failed/, + qr/\*\d+ .*? on_http_call_response \(id: \d+, status: , headers: 0, body_bytes: 0/, + qr/dispatch_status: tls handshake failure/ ] @@ -366,6 +391,8 @@ qr/\[emerg\] .*?no such file/i --- no_error_log [error] [crit] +[alert] +stub --- must_die @@ -380,6 +407,8 @@ qr/\[emerg\] .*?no certificate or crl found/i --- no_error_log [error] [crit] +[alert] +stub --- must_die --- user_files >>> ca.pem @@ -389,7 +418,7 @@ foo === TEST 12: proxy_wasm - dispatch_https_call() no trusted CA macOS: intermitent failures ---- skip_eval: 4: $::osname =~ m/darwin/ +--- skip_eval: $::osname =~ m/darwin/ --- timeout eval: $::ExtTimeout --- main_config eval qq{ @@ -411,7 +440,11 @@ qq{ } } --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - tls certificate verify error: \((18|20):(self-signed certificate|unable to get local issuer certificate)\)/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - tls certificate verify error: \((18|20):(self-signed certificate|unable to get local issuer certificate)\)/, + qr/\*\d+ .*? on_http_call_response \(id: \d+, status: , headers: 0, body_bytes: 0/, + qr/dispatch_status: tls handshake failure/ +] --- no_error_log [crit] [emerg] @@ -420,7 +453,7 @@ qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - tls cer === TEST 13: proxy_wasm - dispatch_https_call() empty trusted CA path macOS: intermitent failures ---- skip_eval: 4: $::osname =~ m/darwin/ +--- skip_eval: $::osname =~ m/darwin/ --- timeout eval: $::ExtTimeout --- main_config eval qq{ @@ -446,7 +479,11 @@ qq{ --- response_body ok --- error_log eval -qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - tls certificate verify error: \((18|20):(self-signed certificate|unable to get local issuer certificate)\)/ +[ + qr/(\[error\]|Uncaught RuntimeError|\s+).*?dispatch failed: tcp socket - tls certificate verify error: \((18|20):(self-signed certificate|unable to get local issuer certificate)\)/, + qr/\*\d+ .*? on_http_call_response \(id: \d+, status: , headers: 0, body_bytes: 0/, + qr/dispatch_status: tls handshake failure/ +] --- no_error_log [crit] @@ -490,6 +527,9 @@ ok qr/upstream tls server name: "hostname"/, qr/checking tls certificate CN for "hostname:\d+" \(sni: "hostname"\)/, ] +--- no_error_log +[error] +[crit] @@ -522,7 +562,11 @@ qq{ --- response_body ok --- error_log eval -qr/could not derive tls sni from host \("127\.0\.0\.1:\d+"\)/ +[ + qr/could not derive tls sni from host \("127\.0\.0\.1:\d+"\)/, + qr/\*\d+ .*? on_http_call_response \(id: \d+, status: , headers: 0, body_bytes: 0/, + qr/dispatch_status: tls handshake failure/ +] --- no_error_log [crit] @@ -552,7 +596,11 @@ SNI cannot be an IP address. --- response_body ok --- error_log eval -qr/could not derive tls sni from host \("\[0:0:0:0:0:0:0:1\]:\d+"\)/ +[ + qr/could not derive tls sni from host \("\[0:0:0:0:0:0:0:1\]:\d+"\)/, + qr/\*\d+ .*? on_http_call_response \(id: \d+, status: , headers: 0, body_bytes: 0/, + qr/dispatch_status: tls handshake failure/ +] --- no_error_log [crit] @@ -595,8 +643,11 @@ ok --- error_log eval [ "upstream tls server name: \"hostname\"", - qr/checking tls certificate CN for "127\.0\.0\.1:\d+" \(sni: "hostname"\)/, + qr/checking tls certificate CN for "127\.0\.0\.1:\d+" \(sni: "hostname"\)/ ] +--- no_error_log +[error] +[crit] @@ -636,6 +687,8 @@ ok --- no_error_log [error] [crit] +[alert] +[emerg] @@ -680,6 +733,9 @@ ok "upstream tls server name: \"hostname\"", "verifying tls certificate for \"unix:$ENV{TEST_NGINX_UNIX_SOCKET}\" (sni: \"hostname\")" ] +--- no_error_log +[error] +[crit] @@ -721,6 +777,8 @@ ok --- no_error_log [error] [crit] +[alert] +[emerg] @@ -762,6 +820,9 @@ qq{ qr/\[warn\] .*? tls certificate host not verified/, "on_root_http_call_response (id: 0, status: 200, headers: 5, body_bytes: 3, trailers: 0)", ] +--- no_error_log +[error] +[crit] @@ -805,3 +866,6 @@ qq{ qr/checking tls certificate CN for "hostname:\d+" \(sni: "hostname"\)/, "on_root_http_call_response (id: 0, status: 200, headers: 5, body_bytes: 3, trailers: 0)", ] +--- no_error_log +[error] +[crit] diff --git a/t/03-proxy_wasm/hfuncs/133-proxy_dispatch_http_edge_cases.t b/t/03-proxy_wasm/hfuncs/133-proxy_dispatch_http_edge_cases.t index 3e93b9255..6374e5741 100644 --- a/t/03-proxy_wasm/hfuncs/133-proxy_dispatch_http_edge_cases.t +++ b/t/03-proxy_wasm/hfuncs/133-proxy_dispatch_http_edge_cases.t @@ -395,10 +395,11 @@ qr/\A.*? on_request_headers.* --- grep_error_log_out eval qr/\A\[error] .*? dispatch failed: tcp socket - Connection refused \[error] .*? dispatch failed: tcp socket - Connection refused\Z/ +--- error_log +dispatch_status: broken connection +dispatch_status: broken connection --- no_error_log [crit] -[emerg] -[alert] @@ -423,10 +424,11 @@ ok --- grep_error_log_out eval qr/\A\[error] .*? dispatch failed: tcp socket - Connection refused \[error] .*? dispatch failed: tcp socket - Connection refused\Z/ +--- error_log +dispatch_status: broken connection +dispatch_status: broken connection --- no_error_log [crit] -[emerg] -[alert] @@ -452,4 +454,4 @@ proxy_wasm http dispatch cancelled --- no_error_log [crit] [emerg] -[alert] +on_http_call_response diff --git a/t/03-proxy_wasm/sdks/002-go_sdk/005-dispatch_call_on_tick.t b/t/03-proxy_wasm/sdks/002-go_sdk/005-dispatch_call_on_tick.t index e14e17946..a1923949b 100644 --- a/t/03-proxy_wasm/sdks/002-go_sdk/005-dispatch_call_on_tick.t +++ b/t/03-proxy_wasm/sdks/002-go_sdk/005-dispatch_call_on_tick.t @@ -24,6 +24,7 @@ Missing IP for "web_service" host requested by the filter. location /t { return 200; } +--- wait: 1 --- ignore_response_body --- error_log eval qr/\[error\] .*? dispatch failed: tcp socket - resolver error: Host not found/ @@ -49,6 +50,7 @@ Connection refused on 127.0.0.1:81 requested by filter. location /t { return 200; } +--- wait: 1 --- ignore_response_body --- error_log eval qr/\[error\] .*? dispatch failed: tcp socket - Connection refused/ diff --git a/t/lib/proxy-wasm-tests/hostcalls/src/filter.rs b/t/lib/proxy-wasm-tests/hostcalls/src/filter.rs index 9f771c645..f3c966c35 100644 --- a/t/lib/proxy-wasm-tests/hostcalls/src/filter.rs +++ b/t/lib/proxy-wasm-tests/hostcalls/src/filter.rs @@ -11,6 +11,7 @@ impl Context for TestHttp { body_size: usize, ntrailers: usize, ) { + let dispatch_status = self.get_http_call_response_header(":dispatch_status"); let status = self.get_http_call_response_header(":status"); let bytes = self.get_http_call_response_body(0, body_size); let op = self @@ -23,6 +24,11 @@ impl Context for TestHttp { token_id, status.unwrap_or("".to_string()), nheaders, body_size, ntrailers, op ); + match dispatch_status.as_deref() { + Some(s) => info!("dispatch_status: {}", s), + None => {} + } + self.add_http_response_header("pwm-call-id", token_id.to_string().as_str()); match op { diff --git a/util/sdks/go.sh b/util/sdks/go.sh index 9e40031e8..d71179ad7 100755 --- a/util/sdks/go.sh +++ b/util/sdks/go.sh @@ -100,6 +100,17 @@ EOF proxywasm.LogCriticalf("dispatch httpcall failed: %v", err) } } +EOF + patch --forward --ignore-whitespace examples/dispatch_call_on_tick/main.go <<'EOF' + @@ -21,7 +21,7 @@ import ( + "github.com/tetratelabs/proxy-wasm-go-sdk/proxywasm/types" + ) + + -const tickMilliseconds uint32 = 100 + +const tickMilliseconds uint32 = 1000 + + func main() { + proxywasm.SetVMContext(&vmContext{}) EOF set -e