misc(proxy-wasm) improve filter chain errors clarity & consistency

* Clarify error messages * Avoid producing an error log and a subsequent warning log, since it distracts from the initial error log. * Carefully separate filter error loggers from filter chain errors (filter vs. host runloop).
Kong · Sep 15, 2023 · 02a689d · 02a689d
1 parent 3bea432
commit 02a689d
Show file tree

Hide file tree

Showing 12 changed files with 50 additions and 91 deletions.
diff --git a/src/common/proxy_wasm/ngx_proxy_wasm.c b/src/common/proxy_wasm/ngx_proxy_wasm.c
@@ -467,13 +467,9 @@ ngx_proxy_wasm_action2rc(ngx_proxy_wasm_ctx_t *pwctx,
         if (!pwexec->ecode_logged
             && pwctx->step != NGX_PROXY_WASM_STEP_DONE)
         {
-            ngx_proxy_wasm_log_error(NGX_LOG_WARN, pwexec->log,
-                                     pwexec->ecode,
-                                     "filter %l/%l failed resuming \"%V\" "
-                                     "step in \"%V\" phase",
-                                     pwexec->index + 1, pwctx->nfilters,
-                                     ngx_proxy_wasm_step_name(pwctx->step),
-                                     &pwctx->phase->name);
+            ngx_proxy_wasm_log_error(NGX_LOG_INFO, pwctx->log, pwexec->ecode,
+                                     "filter chain failed resuming: "
+                                     "previous error");
 
             pwexec->ecode_logged = 1;
         }
@@ -543,34 +539,23 @@ ngx_proxy_wasm_action2rc(ngx_proxy_wasm_ctx_t *pwctx,
             goto yield;
 #endif
         default:
-            if (pwexec->root_id == NGX_PROXY_WASM_ROOT_CTX_ID) {
-                ngx_proxy_wasm_log_error(NGX_LOG_ERR, pwexec->log,
-                                         pwexec->ecode,
-                                         "root context cannot pause in "
-                                         "\"%V\" phase (\"%V\" step)",
-                                         &pwctx->phase->name,
-                                         ngx_proxy_wasm_step_name(pwctx->step));
-
-            } else {
-                ngx_proxy_wasm_log_error(NGX_LOG_ERR, pwexec->log,
-                                         pwexec->ecode,
-                                         "filter %l/%l cannot pause in "
-                                         "\"%V\" phase (\"%V\" step)",
-                                         pwexec->index + 1, pwctx->nfilters,
-                                         &pwctx->phase->name,
-                                         ngx_proxy_wasm_step_name(pwctx->step));
-            }
+            ngx_proxy_wasm_log_error(NGX_LOG_ERR, pwexec->log, pwexec->ecode,
+                                     "bad \"%V\" return action: \"PAUSE\"",
+                                     ngx_proxy_wasm_step_name(pwctx->step));
 
             pwexecs = (ngx_proxy_wasm_exec_t *) pwctx->pwexecs.elts;
             pwexec = &pwexecs[pwctx->exec_index];
-            pwexec->ecode = NGX_PROXY_WASM_ERR_NOT_YIELDABLE;
+            pwexec->ecode = NGX_PROXY_WASM_ERR_RETURN_ACTION;
+            break;
         }
 
         break;
 
     default:
-        ngx_proxy_wasm_log_error(NGX_LOG_WASM_NYI, pwexec->log, 0,
-                                 "NYI - proxy_wasm action: %d", action);
+        ngx_proxy_wasm_log_error(NGX_LOG_WASM_NYI, pwctx->log, 0,
+                                 "NYI - \"%V\" return action: %d",
+                                 ngx_proxy_wasm_step_name(pwctx->step),
+                                 action);
         goto error;
 
     }
@@ -583,8 +568,8 @@ ngx_proxy_wasm_action2rc(ngx_proxy_wasm_ctx_t *pwctx,
 #endif
                     );
 
-    if (rc == NGX_ERROR) {
-        pwexec->ecode = NGX_PROXY_WASM_ERR_NOT_YIELDABLE;
+    if (rc == NGX_ERROR && !pwexec->ecode) {
+        pwexec->ecode = NGX_PROXY_WASM_ERR_UNKNOWN;
     }
 
     goto done;
@@ -680,7 +665,7 @@ ngx_proxy_wasm_run_step(ngx_proxy_wasm_exec_t *pwexec,
         rc = ngx_proxy_wasm_on_tick(pwexec);
         break;
     default:
-        ngx_proxy_wasm_log_error(NGX_LOG_WASM_NYI, pwexec->log, 0,
+        ngx_proxy_wasm_log_error(NGX_LOG_WASM_NYI, pwctx->log, 0,
                                  "NYI - proxy_wasm step: %d", step);
         rc = NGX_ERROR;
         break;
@@ -1486,7 +1471,7 @@ ngx_proxy_wasm_on_start(ngx_proxy_wasm_instance_t *ictx,
                                                 &rets,
                                                 rexec->id, 0);
             if (rc != NGX_OK || !rets->data[0].of.i32) {
-                return NGX_PROXY_WASM_ERR_START_FAILED;
+                return NGX_PROXY_WASM_ERR_VM_START_FAILED;
             }
         }
 
@@ -1495,7 +1480,7 @@ ngx_proxy_wasm_on_start(ngx_proxy_wasm_instance_t *ictx,
                                             &rets,
                                             rexec->id, filter->config.len);
         if (rc != NGX_OK || !rets->data[0].of.i32) {
-            return NGX_PROXY_WASM_ERR_START_FAILED;
+            return NGX_PROXY_WASM_ERR_CONFIGURE_FAILED;
         }
 
         rexec->started = 1;
@@ -1514,7 +1499,7 @@ ngx_proxy_wasm_on_start(ngx_proxy_wasm_instance_t *ictx,
                                             NULL,
                                             pwexec->id, pwexec->root_id);
         if (rc != NGX_OK) {
-            return NGX_PROXY_WASM_ERR_INSTANCE_FAILED;
+            return NGX_PROXY_WASM_ERR_START_FAILED;
         }
 
         pwexec->node.key = pwexec->id;

diff --git a/src/common/proxy_wasm/ngx_proxy_wasm.h b/src/common/proxy_wasm/ngx_proxy_wasm.h
@@ -53,12 +53,13 @@ typedef enum {
     NGX_PROXY_WASM_ERR_BAD_ABI = 2,
     NGX_PROXY_WASM_ERR_BAD_HOST_INTERFACE = 3,
     NGX_PROXY_WASM_ERR_BAD_MODULE_INTERFACE = 4,
-    NGX_PROXY_WASM_ERR_INSTANCE_FAILED = 5,
-    NGX_PROXY_WASM_ERR_INSTANCE_TRAPPED = 6,
-    NGX_PROXY_WASM_ERR_START_FAILED = 7,
+    NGX_PROXY_WASM_ERR_START_FAILED = 5,
+    NGX_PROXY_WASM_ERR_VM_START_FAILED = 6,
+    NGX_PROXY_WASM_ERR_CONFIGURE_FAILED = 7,
     NGX_PROXY_WASM_ERR_DISPATCH_FAILED = 8,
-    NGX_PROXY_WASM_ERR_NOT_YIELDABLE = 9,
-    NGX_PROXY_WASM_ERR_UNKNOWN = 10,
+    NGX_PROXY_WASM_ERR_INSTANCE_TRAPPED = 9,
+    NGX_PROXY_WASM_ERR_RETURN_ACTION = 10,
+    NGX_PROXY_WASM_ERR_UNKNOWN = 11,
 } ngx_proxy_wasm_err_e;
 
 

diff --git a/src/common/proxy_wasm/ngx_proxy_wasm_util.c b/src/common/proxy_wasm/ngx_proxy_wasm_util.c
@@ -21,11 +21,12 @@ static ngx_str_t  ngx_proxy_wasm_errlist[] = {
     ngx_string("incompatible ABI version"),
     ngx_string("incompatible host interface"),
     ngx_string("incompatible SDK interface"),
-    ngx_string("instantiation failed"),
+    ngx_string("on_context_create internal failure"),
+    ngx_string("on_vm_start failure"),
+    ngx_string("on_configure failure"),
+    ngx_string("dispatch failure"),
     ngx_string("instance trapped"),
-    ngx_string("initialization failed"),
-    ngx_string("dispatch failed"),
-    ngx_string("not yieldable"),
+    ngx_string("invalid return action"),
     ngx_string("unknown error")
 };
 

diff --git a/t/03-proxy_wasm/001-on_root_phases.t b/t/03-proxy_wasm/001-on_root_phases.t
@@ -59,31 +59,3 @@ qr/\[info\] .*? on_configure, config_size: 0/
 ]
 --- no_error_log
 [error]
-
-
-
-=== TEST 4: proxy_wasm - on_configure returns false
-'daemon off' must be set to check exit_code is 2
-Valgrind mode already writes 'daemon off'
-HUP mode does not catch the worker exit_code
---- skip_eval: 5: $ENV{TEST_NGINX_USE_HUP} == 1
---- main_config eval
-qq{
-    wasm {
-        module on_phases $ENV{TEST_NGINX_CRATES_DIR}/on_phases.wasm;
-    }
-}.($ENV{TEST_NGINX_USE_VALGRIND} ? '' : 'daemon off;')
---- config
-    location /t {
-        proxy_wasm on_phases 'fail_configure=true';
-        return 200;
-    }
---- error_code: 500
---- response_body_like: 500 Internal Server Error
---- error_log eval
-qr/\[emerg\] .*? failed initializing "on_phases" filter \(initialization failed\)/
---- no_error_log
-[error]
-[crit]
-[alert]
---- must_die: 2
diff --git a/t/03-proxy_wasm/002-on_root_phases_failures.t b/t/03-proxy_wasm/002-on_root_phases_failures.t
@@ -33,7 +33,7 @@ qq{
 [
     qr/\[crit\] .*? panicked at/,
     qr/trap on_vm_start/,
-    qr/\[emerg\] .*? failed initializing "hostcalls" filter \(initialization failed\)/,
+    qr/\[emerg\] .*? failed initializing "hostcalls" filter \(on_vm_start failure\)/,
 ]
 --- must_die: 2
 
@@ -58,7 +58,7 @@ qq{
 --- error_log eval
 [
     qr/\[info\] .*? on_vm_start returning false/,
-    qr/\[emerg\] .*? failed initializing "hostcalls" filter \(initialization failed\)/,
+    qr/\[emerg\] .*? failed initializing "hostcalls" filter \(on_vm_start failure\)/,
 ]
 --- no_error_log
 [crit]
@@ -86,7 +86,7 @@ qq{
 [
     qr/\[crit\] .*? panicked at/,
     qr/trap on_configure/,
-    qr/\[emerg\] .*? failed initializing "hostcalls" filter \(initialization failed\)/,
+    qr/\[emerg\] .*? failed initializing "hostcalls" filter \(on_configure failure\)/,
 ]
 --- must_die: 2
 
@@ -109,7 +109,7 @@ qq{
         return 200;
     }
 --- error_log eval
-qr/\[emerg\] .*? failed initializing "hostcalls" filter \(initialization failed\)/
+qr/\[emerg\] .*? failed initializing "hostcalls" filter \(on_configure failure\)/
 --- no_error_log
 [error]
 [crit]

diff --git a/t/03-proxy_wasm/006-on_http_next_action.t b/t/03-proxy_wasm/006-on_http_next_action.t
@@ -68,8 +68,8 @@ NYI
 --- error_log eval
 [
     qr/pausing after "ResponseHeaders"/,
-    qr#\[error\] .*? filter 1/1 cannot pause in "header_filter" phase#,
-    qr#\[warn\] .*? filter 1/1 failed resuming "on_response_body" step in "body_filter" phase \(not yieldable\)#
+    qr#\[error\] .*? bad "on_response_headers" return action: "PAUSE"#,
+    qr#\[info\] .*? filter chain failed resuming: previous error \(invalid return action\)#
 ]
 
 
@@ -86,8 +86,8 @@ NYI
 --- error_log eval
 [
     qr/pausing after "ResponseBody"/,
-    qr#\[error\] .*? filter 1/1 cannot pause in "body_filter" phase#,
-    qr#\[warn\] .*? filter 1/1 failed resuming "on_log" step in "log" phase \(not yieldable\)#
+    qr#\[error\] .*? bad "on_response_body" return action: "PAUSE"#,
+    qr#\[info\] .*? filter chain failed resuming: previous error \(invalid return action\)#
 ]
 
 
@@ -188,8 +188,8 @@ NYI
 --- error_log eval
 [
     qr/pausing after "ResponseHeaders"/,
-    qr#\[error\] .*? filter 1/1 cannot pause in "header_filter" phase#,
-    qr#\[warn\] .*? filter 1/1 failed resuming "on_response_body" step in "body_filter" phase \(not yieldable\)#
+    qr#\[error\] .*? bad "on_response_headers" return action: "PAUSE"#,
+    qr#\[info\] .*? filter chain failed resuming: previous error \(invalid return action\)#
 ]
 
 
@@ -224,6 +224,6 @@ ok
 --- error_log eval
 [
     qr/pausing after "ResponseBody"/,
-    qr#\[error\] .*? filter 1/1 cannot pause in "body_filter" phase#,
-    qr#\[warn\] .*? filter 1/1 failed resuming "on_response_body" step in "body_filter" phase \(not yieldable\)#
+    qr#\[error\] .*? bad "on_response_body" return action: "PAUSE"#,
+    qr#\[info\] .*? filter chain failed resuming: previous error \(invalid return action\)#
 ]
diff --git a/t/03-proxy_wasm/007-on_http_instance_isolation.t b/t/03-proxy_wasm/007-on_http_instance_isolation.t
@@ -92,7 +92,7 @@ Should recycle the global instance when trapped.
 \*\d+ .*? filter reusing instance[^#*]*
 \*\d+ .*? filter 1\/2 resuming "on_request_headers" step in "rewrite" phase[^#*]*
 (.*?(Uncaught RuntimeError: )?unreachable|\s*wasm trap: wasm `unreachable` instruction executed)[^#*]*
-\*\d+ .*? filter 1\/2 failed resuming "on_response_headers" step in "header_filter" phase \(instance trapped\)[^#*]*
+\*\d+ .*? filter chain failed resuming: previous error \(instance trapped\)[^#*]*
 \*\d+ .*? filter freeing context #\d+ \(1\/2\)[^#*]*
 \*\d+ .*? filter freeing context #\d+ \(2\/2\)\Z/,
 qr/\A\*\d+ .*? filter freeing trapped instance[^#*]*
@@ -202,7 +202,7 @@ qr/\A\*\d+ .*? filter new instance[^#*]*
 \*\d+ .*? filter reusing instance[^#*]*
 \*\d+ .*? filter 1\/2 resuming "on_request_headers" step in "rewrite" phase[^#*]*
 (.*?(Uncaught RuntimeError: )?unreachable|\s*wasm trap: wasm `unreachable` instruction executed)[^#*]*
-\*\d+ .*? filter 1\/2 failed resuming "on_response_headers" step in "header_filter" phase \(instance trapped\)[^#*]*
+\*\d+ .*? filter chain failed resuming: previous error \(instance trapped\)[^#*]*
 \*\d+ .*? filter freeing context #\d+ \(1\/2\)[^#*]*
 \*\d+ .*? filter freeing context #\d+ \(2\/2\)[^#*]*
 \*\d+ .*? freeing "hostcalls" instance in "main" vm[^#*]*\Z/,

diff --git a/t/03-proxy_wasm/hfuncs/102-proxy_send_local_response.t b/t/03-proxy_wasm/hfuncs/102-proxy_send_local_response.t
@@ -316,7 +316,7 @@ qr/testing in "ResponseHeaders"/
 --- grep_error_log eval: qr/(\[error\]|host trap|\[.*?failed resuming).*/
 --- grep_error_log_out eval
 qr/.*?host trap \(bad usage\): response already sent.*
-\[warn\] .*? filter 1\/1 failed resuming "on_response_body" step in "body_filter" phase \(instance trapped\)/
+\[info\] .*? filter chain failed resuming: previous error \(instance trapped\)/
 --- no_error_log
 [alert]
 [stub]

diff --git a/t/03-proxy_wasm/hfuncs/111-proxy_set_http_request_header.t b/t/03-proxy_wasm/hfuncs/111-proxy_set_http_request_header.t
@@ -308,7 +308,7 @@ path: /test
 --- grep_error_log eval: qr/(NYI|\[.*?failed resuming).*/
 --- grep_error_log_out eval
 qr/.*?NYI - cannot set request path with querystring.*
-\[warn\] .*? filter 1\/1 failed resuming "on_response_headers" step in "header_filter" phase \(instance trapped\)/
+\[info\] .*? filter chain failed resuming: previous error \(instance trapped\)/
 --- no_error_log
 [alert]
 [stderr]

diff --git a/t/03-proxy_wasm/hfuncs/114-proxy_set_http_request_body.t b/t/03-proxy_wasm/hfuncs/114-proxy_set_http_request_body.t
@@ -257,8 +257,8 @@ from_request_body
 --- grep_error_log eval: qr/(.*?cannot set|\[.*?failed resuming).*/
 --- grep_error_log_out eval
 qr/.*?host trap \(bad usage\): cannot set request body.*
-\[warn\] .*? \*\d+ .*? filter 1\/1 failed resuming "on_response_body" step in "body_filter" phase \(instance trapped\).*? subrequest: "\/response_headers".*
-\[warn\] .*? \*\d+ .*? filter 1\/1 failed resuming "on_response_body" step in "body_filter" phase \(instance trapped\).*? request: "GET \/t HTTP\/1\.1".*
+\[info\] .*? \*\d+ .*? filter chain failed resuming: previous error \(instance trapped\).*? subrequest: "\/response_headers".*
+\[info\] .*? \*\d+ .*? filter chain failed resuming: previous error \(instance trapped\).*? request: "GET \/t HTTP\/1\.1".*
 \z/
 --- no_error_log
 [alert]

diff --git a/t/03-proxy_wasm/hfuncs/116-proxy_set_http_response_body.t b/t/03-proxy_wasm/hfuncs/116-proxy_set_http_response_body.t
@@ -347,9 +347,9 @@ qr/500 Internal Server Error/
 --- grep_error_log eval: qr/(.*?cannot set|\[.*?failed resuming).*/
 --- grep_error_log_out eval
 qr/.*?host trap \(bad usage\): cannot set response body.*
-\[warn\] .*? filter 1\/2 failed resuming "on_response_headers" step in "header_filter" phase \(instance trapped\).*? subrequest: "\/request_headers".*
+\[info\] .*? \*\d+ .*? filter chain failed resuming: previous error \(instance trapped\).*? subrequest: "\/request_headers".*
 .*?host trap \(bad usage\): cannot set response body.*
-\[warn\] .*? filter 1\/2 failed resuming "on_response_body" step in "body_filter" phase \(instance trapped\).*? subrequest: "\/response_headers".*
+\[info\] .*? \*\d+ .*? filter chain failed resuming: previous error \(instance trapped\).*? subrequest: "\/response_headers".*
 .*?host trap \(bad usage\): cannot set response body.*/
 --- no_error_log
 [alert]

diff --git a/t/04-openresty/ffi/200-proxy_wasm_and_lua_sanity.t b/t/04-openresty/ffi/200-proxy_wasm_and_lua_sanity.t
@@ -368,7 +368,7 @@ qr/\A\*\d+ .*? filter 1\/1 resuming "on_request_headers" step in "rewrite" phase
 --- grep_error_log_out eval
 qr/\A\*\d+ .*? filter 1\/1 resuming "on_request_headers" step in "rewrite" phase[^#*]*
 \*\d+ .*? filter 1\/1 resuming "on_dispatch_response" step in "access" phase[^#*]*
-\*\d+ .*? filter 1\/1 failed resuming "on_response_body" step in "body_filter" phase \(dispatch failed\)[^#*]*
+\*\d+ .*? filter chain failed resuming: previous error \(dispatch failure\)[^#*]*
 \*\d+ .*? filter freeing context #\d+ \(1\/1\)[^#*]*\Z/