diff --git a/src/common/proxy_wasm/ngx_proxy_wasm.c b/src/common/proxy_wasm/ngx_proxy_wasm.c index c0ee1417d..cf9fddfab 100644 --- a/src/common/proxy_wasm/ngx_proxy_wasm.c +++ b/src/common/proxy_wasm/ngx_proxy_wasm.c @@ -327,6 +327,8 @@ ngx_proxy_wasm_ctx(ngx_uint_t *filter_ids, size_t nfilters, pwexec->pool = pool; pwexec->filter = filter; pwexec->parent = pwctx; + pwexec->root_id = filter->id; + pwexec->log = ngx_pcalloc(pwexec->pool, sizeof(ngx_log_t)); if (pwexec->log == NULL) { return NULL; @@ -344,14 +346,12 @@ ngx_proxy_wasm_ctx(ngx_uint_t *filter_ids, size_t nfilters, pwexec->log_ctx.pwexec = pwexec; pwexec->log_ctx.orig_log = log; - ictx = ngx_proxy_wasm_get_instance(filter, pwstore, log); + ictx = ngx_proxy_wasm_get_instance(filter, pwstore, pwexec, log); if (ictx == NULL) { return NULL; } pwexec->ictx = ictx; - pwexec->id = ictx->next_id++; - pwexec->root_id = filter->id; ngx_wasm_assert(pwexec->index + 1 == pwctx->pwexecs.nelts); @@ -461,7 +461,7 @@ ngx_proxy_wasm_action2rc(ngx_proxy_wasm_ctx_t *pwctx, filter = pwexec->filter; action = pwctx->action; - dd("action: %d", action); + dd("enter (pwexec: %p, action: %d)", pwexec, action); if (pwexec->ecode) { if (!pwexec->ecode_logged @@ -611,7 +611,6 @@ ngx_proxy_wasm_run_step(ngx_proxy_wasm_exec_t *pwexec, ngx_proxy_wasm_instance_t *ictx, ngx_proxy_wasm_step_e step) { ngx_int_t rc; - ngx_proxy_wasm_err_e ecode; ngx_proxy_wasm_action_e action = NGX_PROXY_WASM_ACTION_CONTINUE; ngx_proxy_wasm_ctx_t *pwctx = pwexec->parent; ngx_proxy_wasm_filter_t *filter = pwexec->filter; @@ -657,12 +656,6 @@ ngx_proxy_wasm_run_step(ngx_proxy_wasm_exec_t *pwexec, #ifdef NGX_WASM_RESPONSE_TRAILERS case NGX_PROXY_WASM_STEP_RESP_TRAILERS: #endif - ecode = ngx_proxy_wasm_on_start(ictx, filter, 0); - if (ecode != NGX_PROXY_WASM_ERR_NONE) { - pwexec->ecode = ecode; - goto done; - } - rc = filter->subsystem->resume(pwexec, step, &action); break; case NGX_PROXY_WASM_STEP_LOG: @@ -1177,7 +1170,6 @@ ngx_proxy_wasm_init_abi(ngx_proxy_wasm_filter_t *filter) static ngx_int_t ngx_proxy_wasm_start_filter(ngx_proxy_wasm_filter_t *filter) { - ngx_proxy_wasm_err_e ecode; ngx_proxy_wasm_instance_t *ictx; ngx_wasm_assert(filter->loaded); @@ -1190,24 +1182,12 @@ ngx_proxy_wasm_start_filter(ngx_proxy_wasm_filter_t *filter) return NGX_OK; } - ictx = ngx_proxy_wasm_get_instance(filter, filter->store, filter->log); + ictx = ngx_proxy_wasm_get_instance(filter, filter->store, NULL, + filter->log); if (ictx == NULL) { return NGX_ERROR; } - /* - * update instance log - * FFI-injected filters have a valid log while the instance's - * might be outdated. - */ - ngx_wavm_instance_set_data(ictx->instance, ictx, filter->log); - - ecode = ngx_proxy_wasm_on_start(ictx, filter, 1); - if (ecode != NGX_PROXY_WASM_ERR_NONE) { - filter->ecode = ecode; - return NGX_ERROR; - } - filter->started = 1; return NGX_OK; @@ -1216,12 +1196,16 @@ ngx_proxy_wasm_start_filter(ngx_proxy_wasm_filter_t *filter) ngx_proxy_wasm_instance_t * ngx_proxy_wasm_get_instance(ngx_proxy_wasm_filter_t *filter, - ngx_proxy_wasm_store_t *store, ngx_log_t *log) + ngx_proxy_wasm_store_t *store, ngx_proxy_wasm_exec_t *pwexec, + ngx_log_t *log) { ngx_queue_t *q; ngx_pool_t *pool; ngx_wavm_module_t *module = filter->module; - ngx_proxy_wasm_instance_t *ictx = NULL; + ngx_proxy_wasm_instance_t *ictx; + ngx_proxy_wasm_err_e ecode; + + dd("enter (pwexec: %p)", pwexec); if (store == NULL) { dd("no store, jump to create"); @@ -1250,7 +1234,7 @@ ngx_proxy_wasm_get_instance(ngx_proxy_wasm_filter_t *filter, } if (ictx->module == filter->module) { - dd("reuse instance"); + dd("reuse busy instance"); ngx_wasm_assert(ictx->nrefs); goto reuse; } @@ -1262,17 +1246,29 @@ ngx_proxy_wasm_get_instance(ngx_proxy_wasm_filter_t *filter, { ictx = ngx_queue_data(q, ngx_proxy_wasm_instance_t, q); + if (ictx->instance->trapped) { + ngx_proxy_wasm_log_error(NGX_LOG_DEBUG, log, 0, + "\"%V\" filter freeing trapped instance " + "(ictx: %p, store: %p)", + filter->name, ictx, store); + + q = ngx_queue_next(&ictx->q); + ngx_proxy_wasm_release_instance(ictx, 1); + continue; + } + if (ictx->module == filter->module) { + dd("reuse free instance"); ngx_wasm_assert(ictx->nrefs == 0); ngx_queue_remove(&ictx->q); goto reuse; } } - dd("create instance in store: %p", store); - create: + dd("create instance in store: %p", store); + ictx = ngx_pcalloc(pool, sizeof(ngx_proxy_wasm_instance_t)); if (ictx == NULL) { goto error; @@ -1302,10 +1298,6 @@ ngx_proxy_wasm_get_instance(ngx_proxy_wasm_filter_t *filter, goto done; -error: - - return NULL; - reuse: ngx_proxy_wasm_log_error(NGX_LOG_DEBUG, log, 0, @@ -1313,15 +1305,56 @@ ngx_proxy_wasm_get_instance(ngx_proxy_wasm_filter_t *filter, "(ictx: %p, nrefs: %d, store: %p)", filter->name, ictx, ictx->nrefs + 1, store); + goto done; + done: if (store && !ictx->nrefs) { ngx_queue_insert_tail(&store->busy, &ictx->q); } + if (pwexec) { + if (pwexec->root_id != NGX_PROXY_WASM_ROOT_CTX_ID) { + ngx_wasm_assert(pwexec->id == 0); + pwexec->id = ictx->next_id++; + } + + if (pwexec->ecode) { + /* recycled instance */ + pwexec->ecode = NGX_PROXY_WASM_ERR_NONE; + pwexec->ecode_logged = 0; + } + } + ictx->nrefs++; + ictx->pwexec = pwexec; + + /** + * update instance log + * FFI-injected filters have a valid log while the instance's + * might be outdated. + */ + ngx_wavm_instance_set_data(ictx->instance, ictx, log); + + /* create wasm context (root/http) */ + + ecode = ngx_proxy_wasm_on_start(ictx, filter, pwexec == NULL); + if (ecode != NGX_PROXY_WASM_ERR_NONE) { + if (pwexec) { + pwexec->ecode = ecode; + + } else { + filter->ecode = ecode; + } + + goto error; + } return ictx; + +error: + + return NULL; } @@ -1421,6 +1454,8 @@ ngx_proxy_wasm_on_start(ngx_proxy_wasm_instance_t *ictx, ngx_wavm_instance_t *instance = ictx->instance; wasm_val_vec_t *rets; + dd("enter (pwexec: %p, ictx: %p)", pwexec, ictx); + rexec = ngx_proxy_wasm_root_lookup(ictx, filter->id); if (rexec == NULL) { rexec = ngx_pcalloc(ictx->pool, sizeof(ngx_proxy_wasm_exec_t)); diff --git a/src/common/proxy_wasm/ngx_proxy_wasm.h b/src/common/proxy_wasm/ngx_proxy_wasm.h index e3902fdbc..01f3cee66 100644 --- a/src/common/proxy_wasm/ngx_proxy_wasm.h +++ b/src/common/proxy_wasm/ngx_proxy_wasm.h @@ -398,7 +398,7 @@ ngx_wavm_ptr_t ngx_proxy_wasm_alloc(ngx_proxy_wasm_exec_t *pwexec, size_t size); void ngx_proxy_wasm_store_destroy(ngx_proxy_wasm_store_t *store); ngx_proxy_wasm_instance_t *ngx_proxy_wasm_get_instance( ngx_proxy_wasm_filter_t *filter, ngx_proxy_wasm_store_t *store, - ngx_log_t *log); + ngx_proxy_wasm_exec_t *pwexec, ngx_log_t *log); void ngx_proxy_wasm_release_instance(ngx_proxy_wasm_instance_t *ictx, unsigned sweep); diff --git a/src/common/proxy_wasm/ngx_proxy_wasm_properties.c b/src/common/proxy_wasm/ngx_proxy_wasm_properties.c index 6af10b3e3..8189ee179 100644 --- a/src/common/proxy_wasm/ngx_proxy_wasm_properties.c +++ b/src/common/proxy_wasm/ngx_proxy_wasm_properties.c @@ -721,7 +721,6 @@ ngx_proxy_wasm_properties_get_ngx(ngx_proxy_wasm_ctx_t *pwctx, hash = hash_str(name.data, name.len); rctx = (ngx_http_wasm_req_ctx_t *) pwctx->data; - if (rctx == NULL || rctx->fake_request) { ngx_wavm_log_error(NGX_LOG_ERR, pwctx->log, NULL, "cannot get ngx properties outside of a request"); @@ -861,8 +860,8 @@ static ngx_int_t ngx_proxy_wasm_properties_get_host(ngx_proxy_wasm_ctx_t *pwctx, ngx_str_t *path, ngx_str_t *value) { - host_props_node_t *hpn; uint32_t hash; + host_props_node_t *hpn; #ifdef NGX_WASM_HTTP ngx_http_wasm_req_ctx_t *rctx = pwctx->data; @@ -893,9 +892,9 @@ static ngx_int_t ngx_proxy_wasm_properties_set_host(ngx_proxy_wasm_ctx_t *pwctx, ngx_str_t *path, ngx_str_t *value) { - host_props_node_t *hpn; uint32_t hash; unsigned new_entry = 1; + host_props_node_t *hpn; #ifdef NGX_WASM_HTTP ngx_http_wasm_req_ctx_t *rctx = pwctx->data; diff --git a/src/common/proxy_wasm/ngx_proxy_wasm_util.c b/src/common/proxy_wasm/ngx_proxy_wasm_util.c index 813838978..a8eb5bc53 100644 --- a/src/common/proxy_wasm/ngx_proxy_wasm_util.c +++ b/src/common/proxy_wasm/ngx_proxy_wasm_util.c @@ -212,7 +212,8 @@ ngx_proxy_wasm_filter_tick_handler(ngx_event_t *ev) return; } - ictx = ngx_proxy_wasm_get_instance(filter, filter->store, filter->log); + ictx = ngx_proxy_wasm_get_instance(filter, filter->store, pwexec, + filter->log); if (ictx == NULL) { ngx_wasm_log_error(NGX_LOG_ERR, log, 0, "tick_handler: no instance"); @@ -246,6 +247,8 @@ ngx_proxy_wasm_filter_tick_handler(ngx_event_t *ev) pwexec->ev->data = pwexec; pwexec->ev->log = log; + dd("scheduling next tick in %ld", pwexec->tick_period); + ngx_add_timer(pwexec->ev, pwexec->tick_period); } diff --git a/src/wasm/vm/ngx_wavm.c b/src/wasm/vm/ngx_wavm.c index 13a987eed..ade694c87 100644 --- a/src/wasm/vm/ngx_wavm.c +++ b/src/wasm/vm/ngx_wavm.c @@ -1461,7 +1461,7 @@ ngx_wavm_log_error(ngx_uint_t level, ngx_log_t *log, ngx_wrt_err_t *e, wasm_byte_vec_delete(&trapmsg); #if (NGX_WASM_HAVE_V8 || NGX_WASM_HAVE_WASMER) - if (ctx->instance) { + if (ctx && ctx->instance) { wasm_trap_trace(e->trap, &trace); if (trace.size > 0) { diff --git a/t/03-proxy_wasm/003-on_tick.t b/t/03-proxy_wasm/003-on_tick.t index ebe611a06..d557e4ad2 100644 --- a/t/03-proxy_wasm/003-on_tick.t +++ b/t/03-proxy_wasm/003-on_tick.t @@ -152,3 +152,31 @@ qr/.*?(\[error\]|Uncaught RuntimeError: |\s+)tick_period already set.* [stub2] [stub3] --- must_die + + + +=== TEST 6: proxy_wasm - on_tick with trap +Should recycle the root instance +Should not prevent http context/instance from starting +--- skip_no_debug: 7 +--- wasm_modules: on_phases +--- config + location /t { + proxy_wasm on_phases 'tick_period=200 on_tick=trap'; + return 200; + } +--- response_body +--- grep_error_log eval: qr/\[(info|crit)].*?on_tick.*/ +--- grep_error_log_out eval +qr/.*? +\[info\] .*? on_tick 200.* +\[crit\] .*? panicked at 'on_tick trap'.* +.*? +\[info\] .*? on_tick 200.* +\[crit\] .*? panicked at 'on_tick trap'.*/ +--- error_log +filter 1/1 resuming "on_request_headers" step +filter 1/1 resuming "on_response_headers" step +--- no_error_log +[emerg] +[alert] diff --git a/t/03-proxy_wasm/007-on_http_instance_isolation.t b/t/03-proxy_wasm/007-on_http_instance_isolation.t index fc9f7d18f..6dcd369ee 100644 --- a/t/03-proxy_wasm/007-on_http_instance_isolation.t +++ b/t/03-proxy_wasm/007-on_http_instance_isolation.t @@ -137,11 +137,11 @@ should use an instance per stream #0 on_vm_start[^#*]* #0 on_configure[^#*]* \*\d+ .*? filter new instance[^#*]* +#0 on_configure[^#*]* \*\d+ .*? filter reusing instance[^#*]* -\*\d+ .*? filter 1\/2 resuming "on_request_headers" step in "rewrite" phase[^#*]* #0 on_configure[^#*]* +\*\d+ .*? filter 1\/2 resuming "on_request_headers" step in "rewrite" phase[^#*]* \*\d+ .*? filter 2\/2 resuming "on_request_headers" step in "rewrite" phase[^#*]* -#0 on_configure[^#*]* \*\d+ .*? filter 1\/2 resuming "on_response_headers" step in "header_filter" phase[^#*]* \*\d+ .*? filter 2\/2 resuming "on_response_headers" step in "header_filter" phase[^#*]* \*\d+ .*? filter 1\/2 resuming "on_response_body" step in "body_filter" phase[^#*]* @@ -156,11 +156,11 @@ should use an instance per stream \*\d+ .*? filter freeing context #\d+ \(2\/2\)[^#*]* \*\d+ .*? freeing "hostcalls" instance in "main" vm[^#*]*\Z/, qr/\A\*\d+ .*? filter new instance[^#*]* +#0 on_configure[^#*]* \*\d+ .*? filter reusing instance[^#*]* -\*\d+ .*? filter 1\/2 resuming "on_request_headers" step in "rewrite" phase[^#*]* #0 on_configure[^#*]* +\*\d+ .*? filter 1\/2 resuming "on_request_headers" step in "rewrite" phase[^#*]* \*\d+ .*? filter 2\/2 resuming "on_request_headers" step in "rewrite" phase[^#*]* -#0 on_configure[^#*]* \*\d+ .*? filter 1\/2 resuming "on_response_headers" step in "header_filter" phase[^#*]* \*\d+ .*? filter 2\/2 resuming "on_response_headers" step in "header_filter" phase[^#*]* \*\d+ .*? filter 1\/2 resuming "on_response_body" step in "body_filter" phase[^#*]* diff --git a/t/03-proxy_wasm/hfuncs/120-proxy_properties_get_host.t b/t/03-proxy_wasm/hfuncs/120-proxy_properties_get_host.t index 0df575cb2..705c2fa3b 100644 --- a/t/03-proxy_wasm/hfuncs/120-proxy_properties_get_host.t +++ b/t/03-proxy_wasm/hfuncs/120-proxy_properties_get_host.t @@ -80,8 +80,8 @@ qr/.*?testing in "RequestHeaders".* .*?testing in "Log".* .*?wasmx\.something: 5.*/ --- no_error_log -[error] -[crit] +[emerg] +[alert] @@ -101,8 +101,8 @@ TODO: is this behavior correct? --- error_log eval qr/\[info\] .*? property not found: wasmx.nonexistent_property,/ --- no_error_log -[error] [emerg] +[alert] @@ -123,8 +123,8 @@ ok --- error_log eval qr/\[info\] .*? property not found: was,/ --- no_error_log -[crit] [emerg] +[alert] @@ -137,7 +137,7 @@ is global (single instance for root/request). --- load_nginx_modules: ngx_http_echo_module --- config location /t { - proxy_wasm hostcalls 'tick_period=10 \ + proxy_wasm hostcalls 'tick_period=100 \ on_tick=log_property \ name=wasmx.my_var'; echo_sleep 0.150; @@ -167,7 +167,7 @@ HTTP 200 since the root and request instances are different. location /t { proxy_wasm_isolation stream; - proxy_wasm hostcalls 'tick_period=10 \ + proxy_wasm hostcalls 'tick_period=100 \ on_tick=log_property \ name=wasmx.my_var'; echo_sleep 0.150; diff --git a/t/03-proxy_wasm/hfuncs/122-proxy_properties_set_host.t b/t/03-proxy_wasm/hfuncs/122-proxy_properties_set_host.t index 99ef2524a..abe7b0aa0 100644 --- a/t/03-proxy_wasm/hfuncs/122-proxy_properties_set_host.t +++ b/t/03-proxy_wasm/hfuncs/122-proxy_properties_set_host.t @@ -58,9 +58,9 @@ qr/\A\[info\] .*? new: "2" \[info\] .*? old: "5" \[info\] .*? new: "6"/ --- no_error_log -[error] -[crit] [emerg] +[alert] +[stub] @@ -85,7 +85,7 @@ qr/\A\[info\] .*? new: "2" qr/\[info\] .*? new: unset/, ] --- no_error_log -[error] +[emerg] @@ -110,7 +110,7 @@ qr/\A\[info\] .*? new: "2" qr/\[info\] .*? new: ""/, ] --- no_error_log -[error] +[emerg] @@ -132,9 +132,9 @@ Does not fail when the property is not found. qr/\[info\] .*? new: unset/, ] --- no_error_log -[error] -[crit] [emerg] +[alert] +[stub] @@ -149,7 +149,7 @@ isolation is global (single instance for root/request). set $my_var 123; location /t { - proxy_wasm hostcalls 'tick_period=10 \ + proxy_wasm hostcalls 'tick_period=100 \ on_tick=set_property \ name=wasmx.my_var \ show_old=false \ @@ -186,7 +186,7 @@ ngx_http_* calls. location /t { proxy_wasm_isolation stream; - proxy_wasm hostcalls 'tick_period=10 \ + proxy_wasm hostcalls 'tick_period=100 \ on_tick=set_property \ name=wasmx.my_var \ show_old=false \ diff --git a/t/03-proxy_wasm/hfuncs/123-proxy_properties_set_ngx.t b/t/03-proxy_wasm/hfuncs/123-proxy_properties_set_ngx.t index 492b37e63..370854afe 100644 --- a/t/03-proxy_wasm/hfuncs/123-proxy_properties_set_ngx.t +++ b/t/03-proxy_wasm/hfuncs/123-proxy_properties_set_ngx.t @@ -61,8 +61,8 @@ qr/\A\[info\] .*? old: "1" \[info\] .*? old: "5" \[info\] .*? new: "6"/ --- no_error_log -[error] -[crit] +[emerg] +[alert] @@ -134,8 +134,8 @@ GET /t?hello=world qr/\[info\] .*? new: unset/, ] --- no_error_log -[error] -[crit] +[emerg] +[alert] @@ -238,7 +238,7 @@ HTTP 200 since the root and request instances are different. location /t { proxy_wasm_isolation stream; - proxy_wasm hostcalls 'tick_period=10 \ + proxy_wasm hostcalls 'tick_period=200 \ on_tick=set_property \ name=ngx.my_var \ set=456 \ diff --git a/t/04-openresty/ffi/103-proxy_wasm_attach.t b/t/04-openresty/ffi/103-proxy_wasm_attach.t index a18828d9c..a46421b80 100644 --- a/t/04-openresty/ffi/103-proxy_wasm_attach.t +++ b/t/04-openresty/ffi/103-proxy_wasm_attach.t @@ -515,8 +515,8 @@ qr/\A[^#]*#0 on_vm_start[^#*]* #0 on_configure[^#*]* \*\d+ proxy_wasm initializing filter chain \(nfilters: 1, isolation: 2\)[^#*]* \*\d+ .*? "hostcalls" filter new instance[^#*]* -\*\d+ .*? filter 1\/1 resuming "on_request_headers" step in "rewrite" phase[^#*]* #0 on_configure[^#*]* +\*\d+ .*? filter 1\/1 resuming "on_request_headers" step in "rewrite" phase[^#*]* \*\d+ .*? filter 1\/1 resuming "on_response_headers" step in "header_filter" phase[^#*]* \*\d+ .*? filter 1\/1 resuming "on_response_body" step in "body_filter" phase[^#*]* \*\d+ .*? filter 1\/1 resuming "on_response_body" step in "body_filter" phase[^#*]* @@ -527,8 +527,8 @@ qr/\A[^#]*#0 on_vm_start[^#*]* \*\d+ wasm freeing "hostcalls" instance[^#*]*\Z/, qr/\A\*\d+ proxy_wasm initializing filter chain \(nfilters: 1, isolation: 2\)[^#*]* \*\d+ .*? "hostcalls" filter new instance[^#*]* -\*\d+ .*? filter 1\/1 resuming "on_request_headers" step in "rewrite" phase[^#*]* #0 on_configure[^#*]* +\*\d+ .*? filter 1\/1 resuming "on_request_headers" step in "rewrite" phase[^#*]* \*\d+ .*? filter 1\/1 resuming "on_response_headers" step in "header_filter" phase[^#*]* \*\d+ .*? filter 1\/1 resuming "on_response_body" step in "body_filter" phase[^#*]* \*\d+ .*? filter 1\/1 resuming "on_response_body" step in "body_filter" phase[^#*]* diff --git a/t/lib/proxy-wasm-tests/on-phases/src/filter.rs b/t/lib/proxy-wasm-tests/on-phases/src/filter.rs index 447cc1367..c5e58243f 100644 --- a/t/lib/proxy-wasm-tests/on-phases/src/filter.rs +++ b/t/lib/proxy-wasm-tests/on-phases/src/filter.rs @@ -68,6 +68,12 @@ impl RootContext for HttpHeadersRoot { fn on_tick(&mut self) { info!("on_tick {}", self.config.get("tick_period").unwrap()); + + #[allow(clippy::single_match)] + match self.config.get("on_tick").map(|s| s.as_str()).unwrap_or("") { + "trap" => panic!("on_tick trap"), + _ => (), + } } fn get_type(&self) -> Option {