From b395a9e94bcccbcd2dc238a40dddcff06a2487d4 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 8 Sep 2021 01:48:07 +0800 Subject: [PATCH 01/25] feat(debug-mode): add dynamic debug mode --- apisix/cli/ngx_tpl.lua | 3 + apisix/control/v1.lua | 41 ++- apisix/debug.lua | 44 ++- conf/config-default.yaml | 1 + .../latest/architecture-design/debug-mode.md | 44 +++ docs/en/latest/control-api.md | 7 + .../latest/architecture-design/debug-mode.md | 44 +++ rockspec/apisix-master-0.rockspec | 1 + t/APISIX.pm | 1 + t/debug/dynamic-hook.t | 334 ++++++++++++++++++ t/debug/hook.t | 4 +- 11 files changed, 518 insertions(+), 6 deletions(-) create mode 100644 t/debug/dynamic-hook.t diff --git a/apisix/cli/ngx_tpl.lua b/apisix/cli/ngx_tpl.lua index 3b9b841d3ff5..6470c38daf17 100644 --- a/apisix/cli/ngx_tpl.lua +++ b/apisix/cli/ngx_tpl.lua @@ -188,6 +188,9 @@ http { # for authz-keycloak lua_shared_dict access-tokens {* http.lua_shared_dict["access-tokens"] *}; # cache for service account access tokens + # for dynamic-debug + lua_shared_dict dynamic-debug {* http.lua_shared_dict["dynamic-debug"] *}; # cache for dynamic debug + # for custom shared dict {% if http.lua_shared_dicts then %} {% for cache_key, cache_size in pairs(http.lua_shared_dicts) do %} diff --git a/apisix/control/v1.lua b/apisix/control/v1.lua index 1f200f036593..159d9aaf918d 100644 --- a/apisix/control/v1.lua +++ b/apisix/control/v1.lua @@ -24,7 +24,10 @@ local collectgarbage = collectgarbage local ipairs = ipairs local str_format = string.format local ngx_var = ngx.var - +local req_read_body = ngx.req.read_body +local req_get_body_data = ngx.req.get_body_data +local pairs = pairs +local ngx_shared = ngx.shared local _M = {} @@ -164,6 +167,36 @@ function _M.trigger_gc() end +function _M.advance_debug() + local dict = ngx_shared["dynamic-debug"] + if not dict then + core.log.warn("shared dict dynamic_debug_dict not defined") + return 400 + end + + req_read_body() + local body = req_get_body_data() + + local data, err + if body then + data, err = core.json.decode(body) + if err then + core.log.warn("failed to decode the req body, err: ", err) + return 400 + end + end + + local dynamic_debug_data = "dynamic-debug" + if not data[data.name] or core.table.nkeys(data[data.name]) == 0 then + core.log.warn("no module and function list to hook") + return 400 + end + + local data_str = core.json.encode(data) + dict:set(dynamic_debug_data, data_str) +end + + return { -- /v1/schema { @@ -189,4 +222,10 @@ return { uris = {"/gc"}, handler = _M.trigger_gc, }, + -- /v1/advance_debug + { + methods = {"POST"}, + uris = {"/advance_debug"}, + handler = _M.advance_debug, + }, } diff --git a/apisix/debug.lua b/apisix/debug.lua index 8cd0135c6c94..e7f216e8de6c 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -17,7 +17,6 @@ local require = require local yaml = require("tinyyaml") local log = require("apisix.core.log") -local json = require("apisix.core.json") local profile = require("apisix.core.profile") local process = require("ngx.process") local lfs = require("lfs") @@ -30,6 +29,9 @@ local setmetatable = setmetatable local pcall = pcall local ipairs = ipairs local unpack = unpack +local inspect = require "inspect" +local ngx_shared = ngx.shared +local json_decode = require("apisix.core.json").decode local debug_yaml_path = profile:yaml_path("debug") local debug_yaml local debug_yaml_ctime @@ -38,6 +40,39 @@ local debug_yaml_ctime local _M = {version = 0.1} +local function dynamic() + local dict = ngx_shared["dynamic-debug"] + if not dict then + return nil + end + + local dynamic_debug_data = "dynamic-debug" + local data_str = dict:get(dynamic_debug_data) + if not data_str then + return nil + end + + local data, err = json_decode(data_str) + if err then + log.warn("failed to decode the data string, err: ", err) + return nil + end + + local hook_conf = debug_yaml.hook_conf + hook_conf.enable = data.enable + hook_conf.is_print_input_args = data.is_print_input_args + hook_conf.is_print_return_value = data.is_print_return_value + hook_conf.log_level = data.log_level + hook_conf.name = data.name + + for k, v in pairs(data[data.name]) do + debug_yaml[data.name][k] = v + end + debug_yaml_ctime = ngx.time() + return true +end + + local function read_debug_yaml() local attributes, err = lfs.attributes(debug_yaml_path) if not attributes then @@ -48,6 +83,9 @@ local function read_debug_yaml() -- log.info("change: ", json.encode(attributes)) local last_change_time = attributes.change if debug_yaml_ctime == last_change_time then + if dynamic() then + return + end return end @@ -126,13 +164,13 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) local arg = {...} if hook_conf.is_print_input_args then log[log_level]("call require(\"", file_path, "\").", fun_name, - "() args:", json.delay_encode(arg, true)) + "() args:", inspect(arg)) end local ret = {self.fun_org(...)} if hook_conf.is_print_return_value then log[log_level]("call require(\"", file_path, "\").", fun_name, - "() return:", json.delay_encode(ret, true)) + "() return:", inspect(ret)) end return unpack(ret) end diff --git a/conf/config-default.yaml b/conf/config-default.yaml index ab1f3d4922e2..a75e6ac58dd9 100644 --- a/conf/config-default.yaml +++ b/conf/config-default.yaml @@ -250,6 +250,7 @@ nginx_config: # config for render the template to generate n jwks: 1m introspection: 10m access-tokens: 1m + dynamic-debug: 1m etcd: host: # it's possible to define multiple etcd hosts addresses of the same etcd cluster. diff --git a/docs/en/latest/architecture-design/debug-mode.md b/docs/en/latest/architecture-design/debug-mode.md index bcf17c006201..b3c4e2a223b2 100644 --- a/docs/en/latest/architecture-design/debug-mode.md +++ b/docs/en/latest/architecture-design/debug-mode.md @@ -76,3 +76,47 @@ hook_phase: # Module Function List, Name: hook_phase - http_log_phase #END ``` + +### Dynamic Debug Mode + +Dynamic debug mode can be enabled or disabled dynamically via `/v1/advance_debug` in the [Control API](../control-api.md), with the same configuration parameters and debugging effects as advanced debug mode. + +Example: + +- enable + + ```shell + curl --location --request POST '127.0.0.1:9090/v1/advance_debug' --header 'Content-Type: application/json' --data-raw \ + '{ + "enable": true, + "is_print_input_args": true, + "is_print_return_value": true, + "log_level":"warn", + "name":"hook_phase", + "hook_phase":{ + "apisix":[ + "http_access_phase", + "http_header_filter_phase" + ] + } + }' + ``` + +- disable + + ```shell + curl --location --request POST '127.0.0.1:9090/v1/advance_debug' --header 'Content-Type: application/json' --data-raw \ + '{ + "enable": false, + "is_print_input_args": true, + "is_print_return_value": true, + "log_level":"warn", + "name":"hook_phase", + "hook_phase":{ + "apisix":[ + "http_access_phase", + "http_header_filter_phase" + ] + } + }' + ``` diff --git a/docs/en/latest/control-api.md b/docs/en/latest/control-api.md index 8f36489fcbba..028688ec5a25 100644 --- a/docs/en/latest/control-api.md +++ b/docs/en/latest/control-api.md @@ -204,3 +204,10 @@ Introduced since `v2.8`. Trigger a full GC in the http subsystem. Note that when you enable stream proxy, APISIX will run another Lua VM for the stream subsystem. It won't trigger a full GC in this Lua VM . + +### POST /v1/advance_debug + +Introduced since `v3.0`. + +Dynamically enable or disable the advanced debug mode, see [Dynamic Debug Mode](./architecture-design/debug-mode.md#dynamic-debug-mode) for more information. + diff --git a/docs/zh/latest/architecture-design/debug-mode.md b/docs/zh/latest/architecture-design/debug-mode.md index ce733cf4be49..b80d0e739f97 100644 --- a/docs/zh/latest/architecture-design/debug-mode.md +++ b/docs/zh/latest/architecture-design/debug-mode.md @@ -78,3 +78,47 @@ hook_phase: # 模块函数列表，名字：hook_phase - http_log_phase #END ``` + +### 动态调试模式 + +动态调试模式可通过 [Control API](../../../en/latest/control-api.md) 中的 `/v1/advance_debug` 动态开启或关闭，配置参数和调试效果与高级调试模式一致。 + +示例： + +- 开启 + + ```shell + curl --location --request POST '127.0.0.1:9090/v1/advance_debug' --header 'Content-Type: application/json' --data-raw \ + '{ + "enable": true, + "is_print_input_args": true, + "is_print_return_value": true, + "log_level":"warn", + "name":"hook_phase", + "hook_phase":{ + "apisix":[ + "http_access_phase", + "http_header_filter_phase" + ] + } + }' + ``` + +- 关闭 + + ```shell + curl --location --request POST '127.0.0.1:9090/v1/advance_debug' --header 'Content-Type: application/json' --data-raw \ + '{ + "enable": false, + "is_print_input_args": true, + "is_print_return_value": true, + "log_level":"warn", + "name":"hook_phase", + "hook_phase":{ + "apisix":[ + "http_access_phase", + "http_header_filter_phase" + ] + } + }' + ``` diff --git a/rockspec/apisix-master-0.rockspec b/rockspec/apisix-master-0.rockspec index 7dd1c937608f..0aa818250afd 100644 --- a/rockspec/apisix-master-0.rockspec +++ b/rockspec/apisix-master-0.rockspec @@ -69,6 +69,7 @@ dependencies = { "ext-plugin-proto = 0.3.0", "casbin = 1.26.0", "api7-snowflake = 2.0-1", + "inspect == 3.1.1", } build = { diff --git a/t/APISIX.pm b/t/APISIX.pm index 5b960cc87f8b..9dbb1618e7f1 100644 --- a/t/APISIX.pm +++ b/t/APISIX.pm @@ -445,6 +445,7 @@ _EOC_ lua_shared_dict plugin-api-breaker 10m; lua_capture_error_log 1m; # plugin error-log-logger lua_shared_dict etcd-cluster-health-check 10m; # etcd health check + lua_shared_dict dynamic-debug 1m; # cache for dynamic debug proxy_ssl_name \$upstream_host; proxy_ssl_server_name on; diff --git a/t/debug/dynamic-hook.t b/t/debug/dynamic-hook.t new file mode 100644 index 000000000000..f0e3a8e7569a --- /dev/null +++ b/t/debug/dynamic-hook.t @@ -0,0 +1,334 @@ +# +# Licensed to the Apache Software Foundation (ASF) under one or more +# contributor license agreements. See the NOTICE file distributed with +# this work for additional information regarding copyright ownership. +# The ASF licenses this file to You under the Apache License, Version 2.0 +# (the "License"); you may not use this file except in compliance with +# the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# +use t::APISIX 'no_plan'; + +repeat_each(1); +log_level('info'); +no_root_location(); +no_shuffle(); + +sub read_file($) { + my $infile = shift; + open my $in, $infile + or die "cannot open $infile for reading: $!"; + my $cert = do { local $/; <$in> }; + close $in; + $cert; +} + +our $debug_config = read_file("conf/debug.yaml"); + +run_tests(); + +__DATA__ + +=== TEST 1: dynamic enable +--- debug_config eval: $::debug_config +--- config + location /t { + content_by_lua_block { + local t = require("lib.test_admin").test + local code, body = t('/v1/advance_debug', + ngx.HTTP_POST, + [[{ + "enable": true, + "is_print_input_args": true, + "is_print_return_value": true, + "log_level":"warn", + "name":"hook_phase", + "hook_phase": { + "apisix": [ + "http_access_phase", + "http_header_filter_phase" + ] + } + }]] + ) + + if code >= 300 then + ngx.status = code + return + end + + ngx.sleep(1.1) -- wait for debug timer start + + code, body = t('/apisix/admin/routes/1', + ngx.HTTP_PUT, + [[{ + "uri": "/hello", + "upstream": { + "nodes": { + "127.0.0.1:1980": 1 + }, + "type": "roundrobin" + } + }]] + ) + + if code >= 300 then + ngx.status = code + return + end + + ngx.sleep(0.6) -- wait for sync + + local code, err, org_body = t('/hello') + if code > 300 then + ngx.log(ngx.ERR, err) + return + end + + ngx.sleep(1.1) -- wait for debug timer exec + + ngx.print(org_body) + } + } +--- request +GET /t +--- wait: 3 +--- timeout: 5 +--- response_body +hello world +--- error_log +call require("apisix").http_access_phase() args:{} +call require("apisix").http_access_phase() return:{} +call require("apisix").http_header_filter_phase() args:{} +call require("apisix").http_header_filter_phase() return:{} +--- no_error_log +call require("apisix").http_body_filter_phase() args:{} +call require("apisix").http_body_filter_phase() return:{} +call require("apisix").http_log_phase() args:{} +call require("apisix").http_log_phase() return:{} + + + +=== TEST 2: no module and function list to hook +--- debug_config eval: $::debug_config +--- config + location /t { + content_by_lua_block { + local t = require("lib.test_admin").test + local code, body = t('/v1/advance_debug', + ngx.HTTP_POST, + [[{ + "dynamic_enable":true, + "is_print_input_args":true, + "is_print_return_value":true, + "log_level":"warn", + "name":"hook_phase", + "hook_phase": { + } + }]] + ) + ngx.status = code + } + } +--- request +GET /t +--- error_code: 400 +--- ignore_response_body +--- error_log +no module and function list to hook +--- no_error_log +[error] + + + +=== TEST 3: dynamic disable +--- debug_config eval: $::debug_config +--- config + location /t { + content_by_lua_block { + local t = require("lib.test_admin").test + local code, body = t('/v1/advance_debug', + ngx.HTTP_POST, + [[{ + "enable": true, + "is_print_input_args": true, + "is_print_return_value": true, + "log_level":"warn", + "name":"hook_phase", + "hook_phase": { + "apisix": [ + "http_access_phase", + "http_header_filter_phase" + ] + } + }]] + ) + + if code >= 300 then + ngx.status = code + return + end + + ngx.sleep(1.1) -- wait for debug timer start + + code, body = t('/v1/advance_debug', + ngx.HTTP_POST, + [[{ + "enable": false, + "is_print_input_args": true, + "is_print_return_value": true, + "log_level":"warn", + "name":"hook_phase", + "hook_phase": { + "apisix": [ + "http_access_phase", + "http_header_filter_phase" + ] + } + }]] + ) + + if code >= 300 then + ngx.status = code + return + end + + ngx.sleep(1.1) -- wait for debug timer exec + + for i = 1, 8 do + + end + code, body = t('/apisix/admin/routes/1', + ngx.HTTP_PUT, + [[{ + "uri": "/hello", + "upstream": { + "nodes": { + "127.0.0.1:1980": 1 + }, + "type": "roundrobin" + } + }]] + ) + + if code >= 300 then + ngx.status = code + return + end + + ngx.sleep(0.6) -- wait for sync + + local code, err, org_body + for i = 1, 4 do + code, err, org_body = t('/hello') + if code > 300 then + ngx.log(ngx.ERR, err) + return + end + end + + ngx.sleep(1.1) -- wait for debug timer exec + + ngx.print(org_body) + } + } +--- request +GET /t +--- wait: 5 +--- timeout: 7 +--- response_body +hello world +--- no_error_log +call require("apisix").http_access_phase() args:{} +call require("apisix").http_access_phase() return:{} +call require("apisix").http_header_filter_phase() args:{} +call require("apisix").http_header_filter_phase() return:{} + + + +=== TEST 4: dynamic enable for plugin filter +--- debug_config eval: $::debug_config +--- config + location /t { + content_by_lua_block { + local t = require("lib.test_admin").test + local code, body = t('/v1/advance_debug', + ngx.HTTP_POST, + [[{ + "enable": true, + "is_print_input_args": true, + "is_print_return_value": true, + "log_level":"warn", + "name":"hook_phase", + "hook_phase": { + "apisix.plugin": [ + "filter" + ] + } + }]] + ) + + if code >= 300 then + ngx.status = code + return + end + + ngx.sleep(1.1) -- wait for debug timer start + + code, body = t('/apisix/admin/routes/1', + ngx.HTTP_PUT, + [[{ + "uri": "/hello", + "plugins": { + "limit-count": { + "count": 2, + "time_window": 60, + "rejected_code": 503, + "key": "remote_addr" + } + }, + "upstream": { + "nodes": { + "127.0.0.1:1980": 1 + }, + "type": "roundrobin" + } + }]] + ) + + if code >= 300 then + ngx.status = code + return + end + + ngx.sleep(0.6) -- wait for sync + + local code, err, org_body = t('/hello') + if code > 300 then + ngx.log(ngx.ERR, err) + return + end + + ngx.sleep(1.1) -- wait for debug timer exec + + ngx.print(org_body) + } + } +--- request +GET /t +--- wait: 4 +--- timeout: 5 +--- response_body +hello world +--- no_error_log +[error] +--- error_log +filter(): call require("apisix.plugin").filter() args:{ <1>{ +filter(): call require("apisix.plugin").filter() return:{ { { \ No newline at end of file diff --git a/t/debug/hook.t b/t/debug/hook.t index 5b64d3c06843..05c06662ba38 100644 --- a/t/debug/hook.t +++ b/t/debug/hook.t @@ -134,5 +134,5 @@ hello world --- no_error_log [error] --- error_log -filter(): call require("apisix.plugin").filter() args:[{ -filter(): call require("apisix.plugin").filter() return:[[{ +filter(): call require("apisix.plugin").filter() args:{ <1>{ +filter(): call require("apisix.plugin").filter() return:{ { { From dbf2bb638883602d215afd7661466364cbcdd882 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 8 Sep 2021 01:55:28 +0800 Subject: [PATCH 02/25] remove unused variable pairs --- apisix/control/v1.lua | 1 - 1 file changed, 1 deletion(-) diff --git a/apisix/control/v1.lua b/apisix/control/v1.lua index 159d9aaf918d..50158bcdf62a 100644 --- a/apisix/control/v1.lua +++ b/apisix/control/v1.lua @@ -26,7 +26,6 @@ local str_format = string.format local ngx_var = ngx.var local req_read_body = ngx.req.read_body local req_get_body_data = ngx.req.get_body_data -local pairs = pairs local ngx_shared = ngx.shared local _M = {} From 6b5ddaf4d21be601da6322305573156a7a5b1710 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 8 Sep 2021 01:58:28 +0800 Subject: [PATCH 03/25] remove blank lines --- docs/en/latest/control-api.md | 1 - 1 file changed, 1 deletion(-) diff --git a/docs/en/latest/control-api.md b/docs/en/latest/control-api.md index 028688ec5a25..796611b41cc2 100644 --- a/docs/en/latest/control-api.md +++ b/docs/en/latest/control-api.md @@ -210,4 +210,3 @@ Note that when you enable stream proxy, APISIX will run another Lua VM for the s Introduced since `v3.0`. Dynamically enable or disable the advanced debug mode, see [Dynamic Debug Mode](./architecture-design/debug-mode.md#dynamic-debug-mode) for more information. - From dc5c2ba64b26bdf9483b45f8abbb56cac608213d Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 8 Sep 2021 08:33:54 +0800 Subject: [PATCH 04/25] fix IC error --- t/debug/dynamic-hook.t | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/t/debug/dynamic-hook.t b/t/debug/dynamic-hook.t index f0e3a8e7569a..c7f4eabb9510 100644 --- a/t/debug/dynamic-hook.t +++ b/t/debug/dynamic-hook.t @@ -20,6 +20,7 @@ repeat_each(1); log_level('info'); no_root_location(); no_shuffle(); +workers(4); sub read_file($) { my $infile = shift; @@ -331,4 +332,4 @@ hello world [error] --- error_log filter(): call require("apisix.plugin").filter() args:{ <1>{ -filter(): call require("apisix.plugin").filter() return:{ { { \ No newline at end of file +filter(): call require("apisix.plugin").filter() return:{ { { From 48849d4e5c9abed4923e060f410ae70067273ed0 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Sun, 12 Sep 2021 14:03:22 +0800 Subject: [PATCH 05/25] refactor --- apisix/cli/ngx_tpl.lua | 3 - apisix/control/v1.lua | 40 +-- apisix/debug.lua | 81 ++--- apisix/init.lua | 5 + conf/debug.yaml | 3 + .../latest/architecture-design/debug-mode.md | 56 ++-- docs/en/latest/control-api.md | 6 - .../latest/architecture-design/debug-mode.md | 56 ++-- t/APISIX.pm | 1 - t/debug/dynamic-hook.t | 285 ++++++++---------- 10 files changed, 210 insertions(+), 326 deletions(-) diff --git a/apisix/cli/ngx_tpl.lua b/apisix/cli/ngx_tpl.lua index 6470c38daf17..3b9b841d3ff5 100644 --- a/apisix/cli/ngx_tpl.lua +++ b/apisix/cli/ngx_tpl.lua @@ -188,9 +188,6 @@ http { # for authz-keycloak lua_shared_dict access-tokens {* http.lua_shared_dict["access-tokens"] *}; # cache for service account access tokens - # for dynamic-debug - lua_shared_dict dynamic-debug {* http.lua_shared_dict["dynamic-debug"] *}; # cache for dynamic debug - # for custom shared dict {% if http.lua_shared_dicts then %} {% for cache_key, cache_size in pairs(http.lua_shared_dicts) do %} diff --git a/apisix/control/v1.lua b/apisix/control/v1.lua index 50158bcdf62a..1f200f036593 100644 --- a/apisix/control/v1.lua +++ b/apisix/control/v1.lua @@ -24,9 +24,7 @@ local collectgarbage = collectgarbage local ipairs = ipairs local str_format = string.format local ngx_var = ngx.var -local req_read_body = ngx.req.read_body -local req_get_body_data = ngx.req.get_body_data -local ngx_shared = ngx.shared + local _M = {} @@ -166,36 +164,6 @@ function _M.trigger_gc() end -function _M.advance_debug() - local dict = ngx_shared["dynamic-debug"] - if not dict then - core.log.warn("shared dict dynamic_debug_dict not defined") - return 400 - end - - req_read_body() - local body = req_get_body_data() - - local data, err - if body then - data, err = core.json.decode(body) - if err then - core.log.warn("failed to decode the req body, err: ", err) - return 400 - end - end - - local dynamic_debug_data = "dynamic-debug" - if not data[data.name] or core.table.nkeys(data[data.name]) == 0 then - core.log.warn("no module and function list to hook") - return 400 - end - - local data_str = core.json.encode(data) - dict:set(dynamic_debug_data, data_str) -end - - return { -- /v1/schema { @@ -221,10 +189,4 @@ return { uris = {"/gc"}, handler = _M.trigger_gc, }, - -- /v1/advance_debug - { - methods = {"POST"}, - uris = {"/advance_debug"}, - handler = _M.advance_debug, - }, } diff --git a/apisix/debug.lua b/apisix/debug.lua index e7f216e8de6c..fdb25308d5d8 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -30,8 +30,6 @@ local pcall = pcall local ipairs = ipairs local unpack = unpack local inspect = require "inspect" -local ngx_shared = ngx.shared -local json_decode = require("apisix.core.json").decode local debug_yaml_path = profile:yaml_path("debug") local debug_yaml local debug_yaml_ctime @@ -40,39 +38,6 @@ local debug_yaml_ctime local _M = {version = 0.1} -local function dynamic() - local dict = ngx_shared["dynamic-debug"] - if not dict then - return nil - end - - local dynamic_debug_data = "dynamic-debug" - local data_str = dict:get(dynamic_debug_data) - if not data_str then - return nil - end - - local data, err = json_decode(data_str) - if err then - log.warn("failed to decode the data string, err: ", err) - return nil - end - - local hook_conf = debug_yaml.hook_conf - hook_conf.enable = data.enable - hook_conf.is_print_input_args = data.is_print_input_args - hook_conf.is_print_return_value = data.is_print_return_value - hook_conf.log_level = data.log_level - hook_conf.name = data.name - - for k, v in pairs(data[data.name]) do - debug_yaml[data.name][k] = v - end - debug_yaml_ctime = ngx.time() - return true -end - - local function read_debug_yaml() local attributes, err = lfs.attributes(debug_yaml_path) if not attributes then @@ -83,9 +48,6 @@ local function read_debug_yaml() -- log.info("change: ", json.encode(attributes)) local last_change_time = attributes.change if debug_yaml_ctime == last_change_time then - if dynamic() then - return - end return end @@ -186,7 +148,9 @@ end function sync_debug_hooks() if not debug_yaml_ctime or debug_yaml_ctime == pre_mtime then - return + if not (debug_yaml and debug_yaml.http and debug_yaml.http.dynamic) then + return + end end for _, hook in pairs(enabled_hooks) do @@ -238,6 +202,45 @@ local function sync_debug_status(premature) end +local function check() + if not debug_yaml or not debug_yaml.http then + return false + end + + local http = debug_yaml.http + if not http or not http.enable_header_name or not http.dynamic then + return false + end + + return true +end + +function _M.dynamic_enable(headers) + if not check() then + return + end + + if not headers or type(headers) ~= "table" then + return + end + + if headers[debug_yaml.http.enable_header_name] then + debug_yaml.hook_conf.enable = true + sync_debug_hooks() + end +end + + +function _M.dynamic_disable() + if not check() then + return + end + + debug_yaml.hook_conf.enable = false + sync_debug_hooks() +end + + function _M.init_worker() if process.type() ~= "worker" then return diff --git a/apisix/init.lua b/apisix/init.lua index 64879ed67828..f6a7e669f283 100644 --- a/apisix/init.lua +++ b/apisix/init.lua @@ -30,6 +30,7 @@ local upstream_util = require("apisix.utils.upstream") local ctxdump = require("resty.ctxdump") local ipmatcher = require("resty.ipmatcher") local ngx_balancer = require("ngx.balancer") +local debug = require("apisix.debug") local ngx = ngx local get_method = ngx.req.get_method local ngx_exit = ngx.exit @@ -353,6 +354,8 @@ function _M.http_access_phase() core.ctx.set_vars_meta(api_ctx) + debug.dynamic_enable(core.request.headers(api_ctx)) + local uri = api_ctx.var.uri if local_conf.apisix and local_conf.apisix.delete_uri_tail_slash then if str_byte(uri, #uri) == str_byte("/") then @@ -704,6 +707,8 @@ function _M.http_log_phase() core.tablepool.release("matched_route_record", api_ctx.curr_req_matched) end + debug.dynamic_disable() + core.tablepool.release("api_ctx", api_ctx) end diff --git a/conf/debug.yaml b/conf/debug.yaml index b3527e1d5f48..3ea008429fa2 100644 --- a/conf/debug.yaml +++ b/conf/debug.yaml @@ -14,6 +14,9 @@ # See the License for the specific language governing permissions and # limitations under the License. # +http: + dynamic: false # enable or disable this feature + enable_header_name: X-APISIX-Dynamic-Debug # the header name of dynamic enable hook_conf: enable: false # enable or disable this feature name: hook_phase # the name of module and function list diff --git a/docs/en/latest/architecture-design/debug-mode.md b/docs/en/latest/architecture-design/debug-mode.md index b3c4e2a223b2..219ff3cf1308 100644 --- a/docs/en/latest/architecture-design/debug-mode.md +++ b/docs/en/latest/architecture-design/debug-mode.md @@ -77,46 +77,24 @@ hook_phase: # Module Function List, Name: hook_phase #END ``` -### Dynamic Debug Mode +### Dynamic Advanced Debug Mode -Dynamic debug mode can be enabled or disabled dynamically via `/v1/advance_debug` in the [Control API](../control-api.md), with the same configuration parameters and debugging effects as advanced debug mode. +Dynamic advanced debug mode is based on advanced debug mode, which can be enabled dynamically by a single request and turned off automatically when the request ends. Example: -- enable - - ```shell - curl --location --request POST '127.0.0.1:9090/v1/advance_debug' --header 'Content-Type: application/json' --data-raw \ - '{ - "enable": true, - "is_print_input_args": true, - "is_print_return_value": true, - "log_level":"warn", - "name":"hook_phase", - "hook_phase":{ - "apisix":[ - "http_access_phase", - "http_header_filter_phase" - ] - } - }' - ``` - -- disable - - ```shell - curl --location --request POST '127.0.0.1:9090/v1/advance_debug' --header 'Content-Type: application/json' --data-raw \ - '{ - "enable": false, - "is_print_input_args": true, - "is_print_return_value": true, - "log_level":"warn", - "name":"hook_phase", - "hook_phase":{ - "apisix":[ - "http_access_phase", - "http_header_filter_phase" - ] - } - }' - ``` +```yaml +http: + dynamic: true # 是否动态开启高级调试模式 + enable_header_name: X-APISIX-Dynamic-Debug # 对携带此 header 的请求开启高级调试模式 +...... +#END +``` + +Dynamically enable advanced debugging mode, example: + +```shell +curl 127.0.0.1:9090/hello --header 'X-APISIX-Dynamic-Debug: foo' +``` + +Notice: Dynamic advanced debug mode cannot debug the `apisix.http_access_phase` module (because the request enters the `apisix.http_access_phase` module before it determines whether advanced debug mode is dynamically enabled). diff --git a/docs/en/latest/control-api.md b/docs/en/latest/control-api.md index 796611b41cc2..8f36489fcbba 100644 --- a/docs/en/latest/control-api.md +++ b/docs/en/latest/control-api.md @@ -204,9 +204,3 @@ Introduced since `v2.8`. Trigger a full GC in the http subsystem. Note that when you enable stream proxy, APISIX will run another Lua VM for the stream subsystem. It won't trigger a full GC in this Lua VM . - -### POST /v1/advance_debug - -Introduced since `v3.0`. - -Dynamically enable or disable the advanced debug mode, see [Dynamic Debug Mode](./architecture-design/debug-mode.md#dynamic-debug-mode) for more information. diff --git a/docs/zh/latest/architecture-design/debug-mode.md b/docs/zh/latest/architecture-design/debug-mode.md index b80d0e739f97..8e5ae9c98d4f 100644 --- a/docs/zh/latest/architecture-design/debug-mode.md +++ b/docs/zh/latest/architecture-design/debug-mode.md @@ -79,46 +79,24 @@ hook_phase: # 模块函数列表，名字：hook_phase #END ``` -### 动态调试模式 +### 动态高级调试模式 -动态调试模式可通过 [Control API](../../../en/latest/control-api.md) 中的 `/v1/advance_debug` 动态开启或关闭，配置参数和调试效果与高级调试模式一致。 +动态高级调试模式是基于高级调试模式，可以由单个请求动态开启高级调试模式，请求结束后自动关闭。设置 `conf/debug.yaml` 中的选项。 示例： -- 开启 - - ```shell - curl --location --request POST '127.0.0.1:9090/v1/advance_debug' --header 'Content-Type: application/json' --data-raw \ - '{ - "enable": true, - "is_print_input_args": true, - "is_print_return_value": true, - "log_level":"warn", - "name":"hook_phase", - "hook_phase":{ - "apisix":[ - "http_access_phase", - "http_header_filter_phase" - ] - } - }' - ``` - -- 关闭 - - ```shell - curl --location --request POST '127.0.0.1:9090/v1/advance_debug' --header 'Content-Type: application/json' --data-raw \ - '{ - "enable": false, - "is_print_input_args": true, - "is_print_return_value": true, - "log_level":"warn", - "name":"hook_phase", - "hook_phase":{ - "apisix":[ - "http_access_phase", - "http_header_filter_phase" - ] - } - }' - ``` +```yaml +http: + dynamic: true # 是否动态开启高级调试模式 + enable_header_name: X-APISIX-Dynamic-Debug # 对携带此 header 的请求开启高级调试模式 +...... +#END +``` + +动态开启高级调试模式，示例： + +```shell +curl 127.0.0.1:9090/hello --header 'X-APISIX-Dynamic-Debug: foo' +``` + +注意：动态高级调试模式无法调试 `apisix.http_access_phase` 模块（因为请求进入 `apisix.http_access_phase` 模块后，才会判断是否动态开启高级调试模式）。 diff --git a/t/APISIX.pm b/t/APISIX.pm index 9dbb1618e7f1..5b960cc87f8b 100644 --- a/t/APISIX.pm +++ b/t/APISIX.pm @@ -445,7 +445,6 @@ _EOC_ lua_shared_dict plugin-api-breaker 10m; lua_capture_error_log 1m; # plugin error-log-logger lua_shared_dict etcd-cluster-health-check 10m; # etcd health check - lua_shared_dict dynamic-debug 1m; # cache for dynamic debug proxy_ssl_name \$upstream_host; proxy_ssl_server_name on; diff --git a/t/debug/dynamic-hook.t b/t/debug/dynamic-hook.t index c7f4eabb9510..22160060ccb0 100644 --- a/t/debug/dynamic-hook.t +++ b/t/debug/dynamic-hook.t @@ -20,7 +20,6 @@ repeat_each(1); log_level('info'); no_root_location(); no_shuffle(); -workers(4); sub read_file($) { my $infile = shift; @@ -32,6 +31,7 @@ sub read_file($) { } our $debug_config = read_file("conf/debug.yaml"); +$debug_config =~ s/dynamic: false/dynamic: true/; run_tests(); @@ -43,31 +43,7 @@ __DATA__ location /t { content_by_lua_block { local t = require("lib.test_admin").test - local code, body = t('/v1/advance_debug', - ngx.HTTP_POST, - [[{ - "enable": true, - "is_print_input_args": true, - "is_print_return_value": true, - "log_level":"warn", - "name":"hook_phase", - "hook_phase": { - "apisix": [ - "http_access_phase", - "http_header_filter_phase" - ] - } - }]] - ) - - if code >= 300 then - ngx.status = code - return - end - - ngx.sleep(1.1) -- wait for debug timer start - - code, body = t('/apisix/admin/routes/1', + local code, body = t('/apisix/admin/routes/1', ngx.HTTP_PUT, [[{ "uri": "/hello", @@ -87,87 +63,52 @@ __DATA__ ngx.sleep(0.6) -- wait for sync - local code, err, org_body = t('/hello') - if code > 300 then - ngx.log(ngx.ERR, err) - return - end - - ngx.sleep(1.1) -- wait for debug timer exec - - ngx.print(org_body) + local headers = {} + headers["X-APISIX-Dynamic-Debug"] = "" + local code, body = t('/hello', + ngx.HTTP_GET, + "", + nil, + headers + ) + ngx.status = code + ngx.say(body) } } --- request GET /t ---- wait: 3 ---- timeout: 5 +--- wait: 2 +--- timeout: 4 --- response_body -hello world +passed --- error_log -call require("apisix").http_access_phase() args:{} -call require("apisix").http_access_phase() return:{} call require("apisix").http_header_filter_phase() args:{} call require("apisix").http_header_filter_phase() return:{} ---- no_error_log call require("apisix").http_body_filter_phase() args:{} call require("apisix").http_body_filter_phase() return:{} call require("apisix").http_log_phase() args:{} call require("apisix").http_log_phase() return:{} - - - -=== TEST 2: no module and function list to hook ---- debug_config eval: $::debug_config ---- config - location /t { - content_by_lua_block { - local t = require("lib.test_admin").test - local code, body = t('/v1/advance_debug', - ngx.HTTP_POST, - [[{ - "dynamic_enable":true, - "is_print_input_args":true, - "is_print_return_value":true, - "log_level":"warn", - "name":"hook_phase", - "hook_phase": { - } - }]] - ) - ngx.status = code - } - } ---- request -GET /t ---- error_code: 400 ---- ignore_response_body ---- error_log -no module and function list to hook --- no_error_log -[error] +call require("apisix").http_access_phase() args:{} +call require("apisix").http_access_phase() return:{} -=== TEST 3: dynamic disable +=== TEST 2: dynamic enable by per request and disable after handle request --- debug_config eval: $::debug_config --- config location /t { content_by_lua_block { local t = require("lib.test_admin").test - local code, body = t('/v1/advance_debug', - ngx.HTTP_POST, + local code, body = t('/apisix/admin/routes/1', + ngx.HTTP_PUT, [[{ - "enable": true, - "is_print_input_args": true, - "is_print_return_value": true, - "log_level":"warn", - "name":"hook_phase", - "hook_phase": { - "apisix": [ - "http_access_phase", - "http_header_filter_phase" - ] + "uris": ["/hello","/hello1"], + "upstream": { + "nodes": { + "127.0.0.1:1980": 1 + }, + "type": "roundrobin" } }]] ) @@ -177,23 +118,15 @@ no module and function list to hook return end - ngx.sleep(1.1) -- wait for debug timer start + ngx.sleep(0.6) -- wait for sync - code, body = t('/v1/advance_debug', - ngx.HTTP_POST, - [[{ - "enable": false, - "is_print_input_args": true, - "is_print_return_value": true, - "log_level":"warn", - "name":"hook_phase", - "hook_phase": { - "apisix": [ - "http_access_phase", - "http_header_filter_phase" - ] - } - }]] + local headers = {} + headers["X-APISIX-Dynamic-Debug"] = "" -- has the header name of dynamic debug + local code, body = t('/hello1', + ngx.HTTP_GET, + "", + nil, + headers ) if code >= 300 then @@ -201,12 +134,43 @@ no module and function list to hook return end - ngx.sleep(1.1) -- wait for debug timer exec + code, body = t('/hello') -- has no the header name of dynamic debug - for i = 1, 8 do - - end - code, body = t('/apisix/admin/routes/1', + ngx.sleep(1.1) + ngx.status = code + ngx.say(body) + } + } +--- request +GET /t +--- wait: 3 +--- timeout: 5 +--- response_body +passed +--- error_log eval +[qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] +--- no_error_log eval +[qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/] + + + +=== TEST 3: error dynamic enable header +--- debug_config eval: $::debug_config +--- config + location /t { + content_by_lua_block { + local t = require("lib.test_admin").test + local code, body = t('/apisix/admin/routes/1', ngx.HTTP_PUT, [[{ "uri": "/hello", @@ -226,64 +190,56 @@ no module and function list to hook ngx.sleep(0.6) -- wait for sync - local code, err, org_body - for i = 1, 4 do - code, err, org_body = t('/hello') - if code > 300 then - ngx.log(ngx.ERR, err) - return - end - end - - ngx.sleep(1.1) -- wait for debug timer exec - - ngx.print(org_body) + local headers = {} + headers["X-APISIX-Dynamic-Error"] = "" + local code, body = t('/hello', + ngx.HTTP_GET, + "", + nil, + headers + ) + ngx.status = code + ngx.say(body) } } --- request GET /t ---- wait: 5 ---- timeout: 7 +--- wait: 2 +--- timeout: 4 --- response_body -hello world +passed --- no_error_log -call require("apisix").http_access_phase() args:{} -call require("apisix").http_access_phase() return:{} call require("apisix").http_header_filter_phase() args:{} call require("apisix").http_header_filter_phase() return:{} +call require("apisix").http_body_filter_phase() args:{} +call require("apisix").http_body_filter_phase() return:{} +call require("apisix").http_log_phase() args:{} +call require("apisix").http_log_phase() return:{} -=== TEST 4: dynamic enable for plugin filter ---- debug_config eval: $::debug_config +=== TEST 4: plugin filter log +--- debug_config +http: + dynamic_enable: true # enable or disable this feature + enable_header_name: X-APISIX-Dynamic-Debug # the header name of dynamic enable +hook_conf: + enable: true # enable or disable this feature + name: hook_test # the name of module and function list + log_level: warn # log level + is_print_input_args: true # print the input arguments + is_print_return_value: true # print the return value + +hook_test: # module and function list, name: hook_test + apisix.plugin: # required module name + - filter # function name + +#END --- config location /t { content_by_lua_block { local t = require("lib.test_admin").test - local code, body = t('/v1/advance_debug', - ngx.HTTP_POST, - [[{ - "enable": true, - "is_print_input_args": true, - "is_print_return_value": true, - "log_level":"warn", - "name":"hook_phase", - "hook_phase": { - "apisix.plugin": [ - "filter" - ] - } - }]] - ) - - if code >= 300 then - ngx.status = code - return - end - - ngx.sleep(1.1) -- wait for debug timer start - - code, body = t('/apisix/admin/routes/1', + local code, body = t('/apisix/admin/routes/1', ngx.HTTP_PUT, [[{ "uri": "/hello", @@ -295,6 +251,12 @@ call require("apisix").http_header_filter_phase() return:{} "key": "remote_addr" } }, + "upstream": { + "nodes": { + "127.0.0.1:1980": 1 + }, + "type": "roundrobin" + }, "upstream": { "nodes": { "127.0.0.1:1980": 1 @@ -311,23 +273,26 @@ call require("apisix").http_header_filter_phase() return:{} ngx.sleep(0.6) -- wait for sync - local code, err, org_body = t('/hello') - if code > 300 then - ngx.log(ngx.ERR, err) - return - end - - ngx.sleep(1.1) -- wait for debug timer exec + local headers = {} + headers["X-APISIX-Dynamic-Debug"] = "" -- has the header name of dynamic debug + local code, body = t('/hello', + ngx.HTTP_GET, + "", + nil, + headers + ) - ngx.print(org_body) + ngx.sleep(1.1) + ngx.status = code + ngx.say(body) } } --- request GET /t ---- wait: 4 ---- timeout: 5 +--- wait: 2 +--- timeout: 3 --- response_body -hello world +passed --- no_error_log [error] --- error_log From 4480d3902b6e8067841fe26ef85011a54a07244b Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Sun, 12 Sep 2021 14:04:46 +0800 Subject: [PATCH 06/25] remove lua_shared_dict in config-default.yaml --- conf/config-default.yaml | 1 - 1 file changed, 1 deletion(-) diff --git a/conf/config-default.yaml b/conf/config-default.yaml index a75e6ac58dd9..ab1f3d4922e2 100644 --- a/conf/config-default.yaml +++ b/conf/config-default.yaml @@ -250,7 +250,6 @@ nginx_config: # config for render the template to generate n jwks: 1m introspection: 10m access-tokens: 1m - dynamic-debug: 1m etcd: host: # it's possible to define multiple etcd hosts addresses of the same etcd cluster. From c28bb08096f3d39f87830ff95c3f46210402fb3a Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Sun, 12 Sep 2021 14:24:08 +0800 Subject: [PATCH 07/25] fix CI error --- apisix/init.lua | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/apisix/init.lua b/apisix/init.lua index f6a7e669f283..3a89effa9f83 100644 --- a/apisix/init.lua +++ b/apisix/init.lua @@ -30,7 +30,6 @@ local upstream_util = require("apisix.utils.upstream") local ctxdump = require("resty.ctxdump") local ipmatcher = require("resty.ipmatcher") local ngx_balancer = require("ngx.balancer") -local debug = require("apisix.debug") local ngx = ngx local get_method = ngx.req.get_method local ngx_exit = ngx.exit @@ -44,6 +43,7 @@ local str_byte = string.byte local str_sub = string.sub local tonumber = tonumber local control_api_router +local debug local is_http = false if ngx.config.subsystem == "http" then @@ -354,6 +354,7 @@ function _M.http_access_phase() core.ctx.set_vars_meta(api_ctx) + debug = require("apisix.debug") debug.dynamic_enable(core.request.headers(api_ctx)) local uri = api_ctx.var.uri @@ -707,6 +708,7 @@ function _M.http_log_phase() core.tablepool.release("matched_route_record", api_ctx.curr_req_matched) end + debug = require("apisix.debug") debug.dynamic_disable() core.tablepool.release("api_ctx", api_ctx) From c85ce13503b5472df09cf1bca14e21cc9d22d289 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Sun, 12 Sep 2021 15:20:11 +0800 Subject: [PATCH 08/25] fix CI error --- t/debug/dynamic-hook.t | 4 ++-- t/debug/hook.t | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/t/debug/dynamic-hook.t b/t/debug/dynamic-hook.t index 22160060ccb0..1ed384813ea1 100644 --- a/t/debug/dynamic-hook.t +++ b/t/debug/dynamic-hook.t @@ -296,5 +296,5 @@ passed --- no_error_log [error] --- error_log -filter(): call require("apisix.plugin").filter() args:{ <1>{ -filter(): call require("apisix.plugin").filter() return:{ { { +filter(): call require("apisix.plugin").filter() args:{ +filter(): call require("apisix.plugin").filter() return:{ diff --git a/t/debug/hook.t b/t/debug/hook.t index 05c06662ba38..437ccc521657 100644 --- a/t/debug/hook.t +++ b/t/debug/hook.t @@ -134,5 +134,5 @@ hello world --- no_error_log [error] --- error_log -filter(): call require("apisix.plugin").filter() args:{ <1>{ -filter(): call require("apisix.plugin").filter() return:{ { { +filter(): call require("apisix.plugin").filter() args:{ +filter(): call require("apisix.plugin").filter() return:{ From 60d255df09bf443f18037d70d692b4a8ec7fa24a Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Sun, 12 Sep 2021 17:53:40 +0800 Subject: [PATCH 09/25] fix CI error --- apisix/debug.lua | 9 +++------ apisix/init.lua | 2 +- 2 files changed, 4 insertions(+), 7 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index fdb25308d5d8..c23adedf954a 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -18,6 +18,7 @@ local require = require local yaml = require("tinyyaml") local log = require("apisix.core.log") local profile = require("apisix.core.profile") +local request = require("apisix.core.request") local process = require("ngx.process") local lfs = require("lfs") local io = io @@ -215,16 +216,12 @@ local function check() return true end -function _M.dynamic_enable(headers) +function _M.dynamic_enable(api_ctx) if not check() then return end - if not headers or type(headers) ~= "table" then - return - end - - if headers[debug_yaml.http.enable_header_name] then + if request.header(api_ctx, debug_yaml.http.enable_header_name) then debug_yaml.hook_conf.enable = true sync_debug_hooks() end diff --git a/apisix/init.lua b/apisix/init.lua index 3a89effa9f83..a4c3458959ef 100644 --- a/apisix/init.lua +++ b/apisix/init.lua @@ -355,7 +355,7 @@ function _M.http_access_phase() core.ctx.set_vars_meta(api_ctx) debug = require("apisix.debug") - debug.dynamic_enable(core.request.headers(api_ctx)) + debug.dynamic_enable(api_ctx) local uri = api_ctx.var.uri if local_conf.apisix and local_conf.apisix.delete_uri_tail_slash then From 67d39f9f7d103c8e82e48dacdc0c3876c09075e4 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Mon, 13 Sep 2021 11:42:31 +0800 Subject: [PATCH 10/25] chore the require ngx.process to function in debug.lua --- apisix/debug.lua | 2 +- apisix/init.lua | 4 +--- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index c23adedf954a..a98a28cc1777 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -19,7 +19,6 @@ local yaml = require("tinyyaml") local log = require("apisix.core.log") local profile = require("apisix.core.profile") local request = require("apisix.core.request") -local process = require("ngx.process") local lfs = require("lfs") local io = io local ngx = ngx @@ -239,6 +238,7 @@ end function _M.init_worker() + local process = require("ngx.process") if process.type() ~= "worker" then return end diff --git a/apisix/init.lua b/apisix/init.lua index a4c3458959ef..9669fd8fa1a6 100644 --- a/apisix/init.lua +++ b/apisix/init.lua @@ -30,6 +30,7 @@ local upstream_util = require("apisix.utils.upstream") local ctxdump = require("resty.ctxdump") local ipmatcher = require("resty.ipmatcher") local ngx_balancer = require("ngx.balancer") +local debug = require("apisix.debug") local ngx = ngx local get_method = ngx.req.get_method local ngx_exit = ngx.exit @@ -43,7 +44,6 @@ local str_byte = string.byte local str_sub = string.sub local tonumber = tonumber local control_api_router -local debug local is_http = false if ngx.config.subsystem == "http" then @@ -354,7 +354,6 @@ function _M.http_access_phase() core.ctx.set_vars_meta(api_ctx) - debug = require("apisix.debug") debug.dynamic_enable(api_ctx) local uri = api_ctx.var.uri @@ -708,7 +707,6 @@ function _M.http_log_phase() core.tablepool.release("matched_route_record", api_ctx.curr_req_matched) end - debug = require("apisix.debug") debug.dynamic_disable() core.tablepool.release("api_ctx", api_ctx) From dc9c202e6bf62d5f54c6841a4f87f0715596932a Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 15 Sep 2021 00:41:25 +0800 Subject: [PATCH 11/25] save --- apisix/debug.lua | 48 ++++++++++++++++++++++++++---------------- apisix/init.lua | 4 ++-- t/debug/dynamic-hook.t | 8 +++---- 3 files changed, 36 insertions(+), 24 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index a98a28cc1777..4f7f9f1e30a3 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -125,14 +125,31 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) function mt.__call(self, ...) local arg = {...} if hook_conf.is_print_input_args then - log[log_level]("call require(\"", file_path, "\").", fun_name, - "() args:", inspect(arg)) + if hook_conf.enable then + log[log_level]("call require(\"", file_path, "\").", fun_name, + "() args:", inspect(arg)) + end + + if debug_yaml.http.dynamic then + if request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then + log[log_level]("call require(\"", file_path, "\").", fun_name, + "() args:", inspect(arg)) + end + end end local ret = {self.fun_org(...)} if hook_conf.is_print_return_value then - log[log_level]("call require(\"", file_path, "\").", fun_name, - "() return:", inspect(ret)) + if hook_conf.enable then + log[log_level]("call require(\"", file_path, "\").", fun_name, + "() return:", inspect(ret)) + end + if debug_yaml.http.dynamic then + if request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then + log[log_level]("call require(\"", file_path, "\").", fun_name, + "() return:", inspect(ret)) + end + end end return unpack(ret) end @@ -148,7 +165,8 @@ end function sync_debug_hooks() if not debug_yaml_ctime or debug_yaml_ctime == pre_mtime then - if not (debug_yaml and debug_yaml.http and debug_yaml.http.dynamic) then + -- resume enabled_hooks when the specific request end + if not debug_yaml or not debug_yaml.http or not debug_yaml.http.dynamic then return end end @@ -164,7 +182,12 @@ function sync_debug_hooks() local hook_conf = debug_yaml.hook_conf if not hook_conf.enable then pre_mtime = debug_yaml_ctime - return + -- keep the advanced debug triggered by ngx.timer same with the original. + -- if the dynamic debug is triggered by specific request, + -- then ngx.get_phase() is not ngx.timer and http.dynamic must be true. + if ngx.get_phase() == "timer" and debug_yaml.http.dynamic then + return + end end local hook_name = hook_conf.name or "" @@ -215,28 +238,17 @@ local function check() return true end -function _M.dynamic_enable(api_ctx) +function _M.dynamic_debug(api_ctx) if not check() then return end if request.header(api_ctx, debug_yaml.http.enable_header_name) then - debug_yaml.hook_conf.enable = true sync_debug_hooks() end end -function _M.dynamic_disable() - if not check() then - return - end - - debug_yaml.hook_conf.enable = false - sync_debug_hooks() -end - - function _M.init_worker() local process = require("ngx.process") if process.type() ~= "worker" then diff --git a/apisix/init.lua b/apisix/init.lua index 9669fd8fa1a6..903d61f09466 100644 --- a/apisix/init.lua +++ b/apisix/init.lua @@ -354,7 +354,7 @@ function _M.http_access_phase() core.ctx.set_vars_meta(api_ctx) - debug.dynamic_enable(api_ctx) + debug.dynamic_debug(api_ctx) local uri = api_ctx.var.uri if local_conf.apisix and local_conf.apisix.delete_uri_tail_slash then @@ -707,7 +707,7 @@ function _M.http_log_phase() core.tablepool.release("matched_route_record", api_ctx.curr_req_matched) end - debug.dynamic_disable() + debug.dynamic_debug(api_ctx) core.tablepool.release("api_ctx", api_ctx) end diff --git a/t/debug/dynamic-hook.t b/t/debug/dynamic-hook.t index 1ed384813ea1..a751a44f0796 100644 --- a/t/debug/dynamic-hook.t +++ b/t/debug/dynamic-hook.t @@ -87,10 +87,10 @@ call require("apisix").http_header_filter_phase() return:{} call require("apisix").http_body_filter_phase() args:{} call require("apisix").http_body_filter_phase() return:{} call require("apisix").http_log_phase() args:{} -call require("apisix").http_log_phase() return:{} --- no_error_log call require("apisix").http_access_phase() args:{} call require("apisix").http_access_phase() return:{} +call require("apisix").http_log_phase() return:{} @@ -152,15 +152,15 @@ passed qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] --- no_error_log eval [qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/] +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] From 480dc74ebb5d4da80108a9a9aecd26376d763d12 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 15 Sep 2021 09:45:39 +0800 Subject: [PATCH 12/25] save --- apisix/debug.lua | 19 ++++++++++--------- conf/debug.yaml | 2 +- .../latest/architecture-design/debug-mode.md | 10 +++++----- .../latest/architecture-design/debug-mode.md | 4 ++-- t/debug/dynamic-hook.t | 8 ++++---- 5 files changed, 22 insertions(+), 21 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index c0081d418d5b..2a9961a02bf6 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -17,8 +17,8 @@ local require = require local yaml = require("tinyyaml") local log = require("apisix.core.log") -local json = require("apisix.core.json") local profile = require("apisix.core.profile") +local request = require("apisix.core.request") local lfs = require("lfs") local io = io local ngx = ngx @@ -130,8 +130,8 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) "() args:", inspect(arg)) end - if debug_yaml.http.dynamic then - if request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then + if debug_yaml.http and debug_yaml.http.enable then + if ngx.ctx.api_ctx and request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then log[log_level]("call require(\"", file_path, "\").", fun_name, "() args:", inspect(arg)) end @@ -144,8 +144,8 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) log[log_level]("call require(\"", file_path, "\").", fun_name, "() return:", inspect(ret)) end - if debug_yaml.http.dynamic then - if request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then + if debug_yaml.http and debug_yaml.http.enable then + if ngx.ctx.api_ctx and request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then log[log_level]("call require(\"", file_path, "\").", fun_name, "() return:", inspect(ret)) end @@ -166,7 +166,7 @@ end function sync_debug_hooks() if not debug_yaml_ctime or debug_yaml_ctime == pre_mtime then -- resume enabled_hooks when the specific request end - if not debug_yaml or not debug_yaml.http or not debug_yaml.http.dynamic then + if not debug_yaml or not debug_yaml.http or not debug_yaml.http.enable then return end end @@ -184,8 +184,9 @@ function sync_debug_hooks() pre_mtime = debug_yaml_ctime -- keep the advanced debug triggered by ngx.timer same with the original. -- if the dynamic debug is triggered by specific request, - -- then ngx.get_phase() is not ngx.timer and http.dynamic must be true. - if ngx.get_phase() == "timer" and debug_yaml.http.dynamic then + -- then ngx.get_phase() is not ngx.timer and http.enable must be true. + if (ngx.get_phase() == "timer" or ngx.get_phase() == "log") + and debug_yaml.http.enable then return end end @@ -231,7 +232,7 @@ local function check() end local http = debug_yaml.http - if not http or not http.enable_header_name or not http.dynamic then + if not http or not http.enable_header_name or not http.enable then return false end diff --git a/conf/debug.yaml b/conf/debug.yaml index 2f3088f7da60..7a7a5ad8d640 100644 --- a/conf/debug.yaml +++ b/conf/debug.yaml @@ -17,7 +17,7 @@ basic: enable: false http: - dynamic: false # enable or disable this feature + enable: false # enable or disable this feature enable_header_name: X-APISIX-Dynamic-Debug # the header name of dynamic enable hook_conf: enable: false # enable or disable this feature diff --git a/docs/en/latest/architecture-design/debug-mode.md b/docs/en/latest/architecture-design/debug-mode.md index 951b72ff24f2..17397d8fdd53 100644 --- a/docs/en/latest/architecture-design/debug-mode.md +++ b/docs/en/latest/architecture-design/debug-mode.md @@ -84,16 +84,16 @@ hook_phase: # Module Function List, Name: hook_phase #END ``` -### Dynamic Advanced Debug Mode +### Enable Advanced Debug Mode Dynamically -Dynamic advanced debug mode is based on advanced debug mode, which can be enabled dynamically by a single request and turned off automatically when the request ends. +The advanced debug mode can be enabled dynamically by a single request and turned off automatically when the request ends. Example: ```yaml http: - dynamic: true # 是否动态开启高级调试模式 - enable_header_name: X-APISIX-Dynamic-Debug # 对携带此 header 的请求开启高级调试模式 + enable: true # Enable/Disable Advanced Debug Mode Dynamically + enable_header_name: X-APISIX-Dynamic-Debug # Trace for the request with this header ...... #END ``` @@ -104,4 +104,4 @@ Dynamically enable advanced debugging mode, example: curl 127.0.0.1:9090/hello --header 'X-APISIX-Dynamic-Debug: foo' ``` -Notice: Dynamic advanced debug mode cannot debug the `apisix.http_access_phase` module (because the request enters the `apisix.http_access_phase` module before it determines whether advanced debug mode is dynamically enabled). +Notice: Dynamic advanced debug mode cannot hook the `apisix.http_access_phase` module (because the request enters the `apisix.http_access_phase` module before it determines whether advanced debug mode is dynamically enabled). diff --git a/docs/zh/latest/architecture-design/debug-mode.md b/docs/zh/latest/architecture-design/debug-mode.md index 9463ea75375b..318384c00613 100644 --- a/docs/zh/latest/architecture-design/debug-mode.md +++ b/docs/zh/latest/architecture-design/debug-mode.md @@ -94,8 +94,8 @@ hook_phase: # 模块函数列表，名字：hook_phase ```yaml http: - dynamic: true # 是否动态开启高级调试模式 - enable_header_name: X-APISIX-Dynamic-Debug # 对携带此 header 的请求开启高级调试模式 + enable: true # 是否动态开启高级调试模式 + enable_header_name: X-APISIX-Dynamic-Debug # 追踪携带此 header 的请求 ...... #END ``` diff --git a/t/debug/dynamic-hook.t b/t/debug/dynamic-hook.t index a751a44f0796..14298a8dcf0d 100644 --- a/t/debug/dynamic-hook.t +++ b/t/debug/dynamic-hook.t @@ -31,7 +31,7 @@ sub read_file($) { } our $debug_config = read_file("conf/debug.yaml"); -$debug_config =~ s/dynamic: false/dynamic: true/; +$debug_config =~ s/http:\n enable: false/http:\n enable: true/; run_tests(); @@ -82,15 +82,15 @@ GET /t --- response_body passed --- error_log +call require("apisix").http_access_phase() return:{} call require("apisix").http_header_filter_phase() args:{} call require("apisix").http_header_filter_phase() return:{} call require("apisix").http_body_filter_phase() args:{} call require("apisix").http_body_filter_phase() return:{} call require("apisix").http_log_phase() args:{} +call require("apisix").http_log_phase() return:{} --- no_error_log call require("apisix").http_access_phase() args:{} -call require("apisix").http_access_phase() return:{} -call require("apisix").http_log_phase() return:{} @@ -221,7 +221,7 @@ call require("apisix").http_log_phase() return:{} === TEST 4: plugin filter log --- debug_config http: - dynamic_enable: true # enable or disable this feature + enable: true # enable or disable this feature enable_header_name: X-APISIX-Dynamic-Debug # the header name of dynamic enable hook_conf: enable: true # enable or disable this feature From 01c35d97e8a8e992bbed41692c59caa7e849395d Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 15 Sep 2021 12:05:55 +0800 Subject: [PATCH 13/25] refactor the way of dynamic debug --- apisix/debug.lua | 4 +- apisix/init.lua | 4 +- t/debug/dynamic-hook.t | 126 +++++++++++++++++++++++++++++++++-------- 3 files changed, 107 insertions(+), 27 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index 2a9961a02bf6..24d968a4bf3e 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -239,12 +239,12 @@ local function check() return true end -function _M.dynamic_debug(api_ctx) +function _M.dynamic_debug() if not check() then return end - if request.header(api_ctx, debug_yaml.http.enable_header_name) then + if ngx.req.get_headers()[debug_yaml.http.enable_header_name] then sync_debug_hooks() end end diff --git a/apisix/init.lua b/apisix/init.lua index e5daa479070f..93e077705c82 100644 --- a/apisix/init.lua +++ b/apisix/init.lua @@ -356,7 +356,7 @@ function _M.http_access_phase() core.ctx.set_vars_meta(api_ctx) - debug.dynamic_debug(api_ctx) + debug.dynamic_debug() local uri = api_ctx.var.uri if local_conf.apisix and local_conf.apisix.delete_uri_tail_slash then @@ -723,7 +723,7 @@ function _M.http_log_phase() core.tablepool.release("matched_route_record", api_ctx.curr_req_matched) end - debug.dynamic_debug(api_ctx) + debug.dynamic_debug() core.tablepool.release("api_ctx", api_ctx) end diff --git a/t/debug/dynamic-hook.t b/t/debug/dynamic-hook.t index 14298a8dcf0d..b0baa4c1f752 100644 --- a/t/debug/dynamic-hook.t +++ b/t/debug/dynamic-hook.t @@ -119,48 +119,50 @@ call require("apisix").http_access_phase() args:{} end ngx.sleep(0.6) -- wait for sync - + local http = require "resty.http" + local httpc = http.new() local headers = {} - headers["X-APISIX-Dynamic-Debug"] = "" -- has the header name of dynamic debug - local code, body = t('/hello1', - ngx.HTTP_GET, - "", - nil, - headers - ) - - if code >= 300 then - ngx.status = code + headers["X-APISIX-Dynamic-Debug"] = "" + local uri1 = "http://127.0.0.1:" .. ngx.var.server_port + .. "/hello1" + local res, err = httpc:request_uri(uri1, {method = "GET", headers = headers}) + if not res then + ngx.say(err) return end - code, body = t('/hello') -- has no the header name of dynamic debug + local uri2 = "http://127.0.0.1:" .. ngx.var.server_port + .. "/hello" + res, err = httpc:request_uri(uri2) + if not res then + ngx.say(err) + return + end - ngx.sleep(1.1) - ngx.status = code - ngx.say(body) + ngx.print(res.body) } } --- request GET /t ---- wait: 3 ---- timeout: 5 --- response_body -passed +hello world --- error_log eval -[qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, +[qr/call\srequire\(\"apisix\"\).http_access_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] --- no_error_log eval -[qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, +[qr/call\srequire\(\"apisix\"\).http_access_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_access_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/] @@ -298,3 +300,81 @@ passed --- error_log filter(): call require("apisix.plugin").filter() args:{ filter(): call require("apisix.plugin").filter() return:{ + + + +=== TEST 5: multiple requests, only output logs of the request with enable_header_name +--- debug_config +http: + enable: true + enable_header_name: X-APISIX-Dynamic-Debug +hook_conf: + enable: false + name: hook_test + log_level: warn + is_print_input_args: true + is_print_return_value: true +hook_test: + apisix.plugin: + - filter +#END +--- config + location /t { + content_by_lua_block { + local t = require("lib.test_admin").test + local code, body = t('/apisix/admin/routes/1', + ngx.HTTP_PUT, + [[{ + "uri": "/mysleep*", + "upstream": { + "nodes": { + "127.0.0.1:1980": 1 + }, + "type": "roundrobin" + } + }]] + ) + + if code >= 300 then + ngx.status = code + return + end + + ngx.sleep(0.6) -- wait for sync + + local res, err + local http = require "resty.http" + local httpc = http.new() + for i = 1, 3 do + if i == 1 then + local headers = {} + headers["X-APISIX-Dynamic-Debug"] = "" + local uri = "http://127.0.0.1:" .. ngx.var.server_port + .. "/mysleep?seconds=1" + local res, err = httpc:request_uri(uri, {method = "GET", headers = headers}) + if not res then + ngx.say(err) + return + end + else + local uri = "http://127.0.0.1:" .. ngx.var.server_port + .. "/mysleep?seconds=0.1" + res, err = httpc:request_uri(uri) + if not res then + ngx.say(err) + return + end + end + end + + ngx.say("passed") + } + } +--- request +GET /t +--- response_body +passed +--- error_log eval +qr/call\srequire\(\"apisix.plugin\"\).filter\(\)\sreturn.*GET\s\/mysleep\?seconds\=1\sHTTP\/1.1/ +--- no_error_log eval +qr/call\srequire\(\"apisix.plugin\"\).filter\(\)\sreturn.*GET\s\/mysleep\?seconds\=0.1\sHTTP\/1.1/ From 6b1780571e26dc5005d028e46b4a78615dfcba0f Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 15 Sep 2021 12:13:06 +0800 Subject: [PATCH 14/25] fix code lint --- apisix/debug.lua | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index 24d968a4bf3e..e7c276119b8d 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -131,7 +131,8 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) end if debug_yaml.http and debug_yaml.http.enable then - if ngx.ctx.api_ctx and request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then + if ngx.ctx.api_ctx and + request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then log[log_level]("call require(\"", file_path, "\").", fun_name, "() args:", inspect(arg)) end @@ -145,7 +146,8 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) "() return:", inspect(ret)) end if debug_yaml.http and debug_yaml.http.enable then - if ngx.ctx.api_ctx and request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then + if ngx.ctx.api_ctx and + request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then log[log_level]("call require(\"", file_path, "\").", fun_name, "() return:", inspect(ret)) end From 1f58c6f587467a390f13ca5f95b5d53cf3729107 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 15 Sep 2021 12:19:19 +0800 Subject: [PATCH 15/25] remove unnecessary judgement conditions --- apisix/debug.lua | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index e7c276119b8d..e5d23773128f 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -187,8 +187,7 @@ function sync_debug_hooks() -- keep the advanced debug triggered by ngx.timer same with the original. -- if the dynamic debug is triggered by specific request, -- then ngx.get_phase() is not ngx.timer and http.enable must be true. - if (ngx.get_phase() == "timer" or ngx.get_phase() == "log") - and debug_yaml.http.enable then + if ngx.get_phase() == "timer" and debug_yaml.http.enable then return end end From bca20cc91333e9e16632f388e5ee30df7e88acaa Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 15 Sep 2021 12:32:29 +0800 Subject: [PATCH 16/25] chore require --- apisix/debug.lua | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index e5d23773128f..d25f3227fb09 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -18,11 +18,12 @@ local require = require local yaml = require("tinyyaml") local log = require("apisix.core.log") local profile = require("apisix.core.profile") -local request = require("apisix.core.request") local lfs = require("lfs") local io = io local ngx = ngx local re_find = ngx.re.find +local get_headers = ngx.req.get_headers +local get_phase = ngx.get_phase local type = type local pairs = pairs local setmetatable = setmetatable @@ -132,7 +133,7 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) if debug_yaml.http and debug_yaml.http.enable then if ngx.ctx.api_ctx and - request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then + get_headers()[debug_yaml.http.enable_header_name] then log[log_level]("call require(\"", file_path, "\").", fun_name, "() args:", inspect(arg)) end @@ -147,7 +148,7 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) end if debug_yaml.http and debug_yaml.http.enable then if ngx.ctx.api_ctx and - request.header(ngx.ctx.api_ctx, debug_yaml.http.enable_header_name) then + get_headers()[debug_yaml.http.enable_header_name] then log[log_level]("call require(\"", file_path, "\").", fun_name, "() return:", inspect(ret)) end @@ -187,7 +188,8 @@ function sync_debug_hooks() -- keep the advanced debug triggered by ngx.timer same with the original. -- if the dynamic debug is triggered by specific request, -- then ngx.get_phase() is not ngx.timer and http.enable must be true. - if ngx.get_phase() == "timer" and debug_yaml.http.enable then + if (get_phase() == "timer" or get_phase() == "log") + and debug_yaml.http.enable then return end end @@ -245,7 +247,7 @@ function _M.dynamic_debug() return end - if ngx.req.get_headers()[debug_yaml.http.enable_header_name] then + if get_headers()[debug_yaml.http.enable_header_name] then sync_debug_hooks() end end From bdd63ba0a008c722e5dbcfa87cd4b4818af57d44 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 15 Sep 2021 13:35:40 +0800 Subject: [PATCH 17/25] fix CI error --- t/debug/dynamic-hook.t | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/t/debug/dynamic-hook.t b/t/debug/dynamic-hook.t index b0baa4c1f752..a14b54850e8e 100644 --- a/t/debug/dynamic-hook.t +++ b/t/debug/dynamic-hook.t @@ -78,7 +78,6 @@ __DATA__ --- request GET /t --- wait: 2 ---- timeout: 4 --- response_body passed --- error_log @@ -144,6 +143,7 @@ call require("apisix").http_access_phase() args:{} } --- request GET /t +--- wait: 2 --- response_body hello world --- error_log eval @@ -207,7 +207,6 @@ qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sH --- request GET /t --- wait: 2 ---- timeout: 4 --- response_body passed --- no_error_log @@ -292,7 +291,6 @@ hook_test: # module and function list, name: hook_test --- request GET /t --- wait: 2 ---- timeout: 3 --- response_body passed --- no_error_log @@ -372,6 +370,7 @@ hook_test: } --- request GET /t +--- wait: 2 --- response_body passed --- error_log eval From fd123a34b46f736b3b6d98aeb46440c503c576f3 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 15 Sep 2021 16:53:53 +0800 Subject: [PATCH 18/25] refactor dynamic hook enable logic --- apisix/debug.lua | 48 +++++++------------ apisix/init.lua | 2 - conf/debug.yaml | 2 +- .../latest/architecture-design/debug-mode.md | 2 +- .../latest/architecture-design/debug-mode.md | 4 +- t/debug/dynamic-hook.t | 25 +++++----- 6 files changed, 35 insertions(+), 48 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index d25f3227fb09..d374ff2dcf6e 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -125,33 +125,30 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) function mt.__call(self, ...) local arg = {...} + local http_filter = debug_yaml.http_filter + local api_ctx = ngx.ctx.api_ctx if hook_conf.is_print_input_args then - if hook_conf.enable then + if not (http_filter and http_filter.enable) or (api_ctx and api_ctx.enable_dynamic_debug) then log[log_level]("call require(\"", file_path, "\").", fun_name, "() args:", inspect(arg)) end - if debug_yaml.http and debug_yaml.http.enable then - if ngx.ctx.api_ctx and - get_headers()[debug_yaml.http.enable_header_name] then - log[log_level]("call require(\"", file_path, "\").", fun_name, - "() args:", inspect(arg)) - end + if (http_filter and http_filter.enable) and (api_ctx and api_ctx.enable_dynamic_debug) then + log[log_level]("call require(\"", file_path, "\").", fun_name, + "() args:", inspect(arg)) end end local ret = {self.fun_org(...)} if hook_conf.is_print_return_value then - if hook_conf.enable then + if not (http_filter and http_filter.enable) or (api_ctx and api_ctx.enable_dynamic_debug) then log[log_level]("call require(\"", file_path, "\").", fun_name, "() return:", inspect(ret)) end - if debug_yaml.http and debug_yaml.http.enable then - if ngx.ctx.api_ctx and - get_headers()[debug_yaml.http.enable_header_name] then - log[log_level]("call require(\"", file_path, "\").", fun_name, - "() return:", inspect(ret)) - end + + if (http_filter and http_filter.enable) and (api_ctx and api_ctx.enable_dynamic_debug) then + log[log_level]("call require(\"", file_path, "\").", fun_name, + "() return:", inspect(ret)) end end return unpack(ret) @@ -168,10 +165,7 @@ end function sync_debug_hooks() if not debug_yaml_ctime or debug_yaml_ctime == pre_mtime then - -- resume enabled_hooks when the specific request end - if not debug_yaml or not debug_yaml.http or not debug_yaml.http.enable then - return - end + return end for _, hook in pairs(enabled_hooks) do @@ -185,13 +179,7 @@ function sync_debug_hooks() local hook_conf = debug_yaml.hook_conf if not hook_conf.enable then pre_mtime = debug_yaml_ctime - -- keep the advanced debug triggered by ngx.timer same with the original. - -- if the dynamic debug is triggered by specific request, - -- then ngx.get_phase() is not ngx.timer and http.enable must be true. - if (get_phase() == "timer" or get_phase() == "log") - and debug_yaml.http.enable then - return - end + return end local hook_name = hook_conf.name or "" @@ -230,12 +218,12 @@ end local function check() - if not debug_yaml or not debug_yaml.http then + if not debug_yaml or not debug_yaml.http_filter then return false end - local http = debug_yaml.http - if not http or not http.enable_header_name or not http.enable then + local http_filter = debug_yaml.http_filter + if not http_filter or not http_filter.enable_header_name or not http_filter.enable then return false end @@ -247,8 +235,8 @@ function _M.dynamic_debug() return end - if get_headers()[debug_yaml.http.enable_header_name] then - sync_debug_hooks() + if get_headers()[debug_yaml.http_filter.enable_header_name] then + ngx.ctx.api_ctx.enable_dynamic_debug = true end end diff --git a/apisix/init.lua b/apisix/init.lua index 93e077705c82..defd7bd0913b 100644 --- a/apisix/init.lua +++ b/apisix/init.lua @@ -723,8 +723,6 @@ function _M.http_log_phase() core.tablepool.release("matched_route_record", api_ctx.curr_req_matched) end - debug.dynamic_debug() - core.tablepool.release("api_ctx", api_ctx) end diff --git a/conf/debug.yaml b/conf/debug.yaml index 7a7a5ad8d640..23c8d51a4672 100644 --- a/conf/debug.yaml +++ b/conf/debug.yaml @@ -16,7 +16,7 @@ # basic: enable: false -http: +http_filter: enable: false # enable or disable this feature enable_header_name: X-APISIX-Dynamic-Debug # the header name of dynamic enable hook_conf: diff --git a/docs/en/latest/architecture-design/debug-mode.md b/docs/en/latest/architecture-design/debug-mode.md index 17397d8fdd53..fbbea55a2919 100644 --- a/docs/en/latest/architecture-design/debug-mode.md +++ b/docs/en/latest/architecture-design/debug-mode.md @@ -91,7 +91,7 @@ The advanced debug mode can be enabled dynamically by a single request and turne Example: ```yaml -http: +http_filter: enable: true # Enable/Disable Advanced Debug Mode Dynamically enable_header_name: X-APISIX-Dynamic-Debug # Trace for the request with this header ...... diff --git a/docs/zh/latest/architecture-design/debug-mode.md b/docs/zh/latest/architecture-design/debug-mode.md index 318384c00613..da55c1a14a04 100644 --- a/docs/zh/latest/architecture-design/debug-mode.md +++ b/docs/zh/latest/architecture-design/debug-mode.md @@ -93,7 +93,7 @@ hook_phase: # 模块函数列表，名字：hook_phase 示例： ```yaml -http: +http_filter: enable: true # 是否动态开启高级调试模式 enable_header_name: X-APISIX-Dynamic-Debug # 追踪携带此 header 的请求 ...... @@ -106,4 +106,4 @@ http: curl 127.0.0.1:9090/hello --header 'X-APISIX-Dynamic-Debug: foo' ``` -注意：动态高级调试模式无法调试 `apisix.http_access_phase` 模块（因为请求进入 `apisix.http_access_phase` 模块后，才会判断是否动态开启高级调试模式）。 +注意：动态高级调试模式无法调试 `apisix.http_access_phase`， 模块（因为请求进入 `apisix.http_access_phase` 模块后，才会判断是否动态开启高级调试模式）。 diff --git a/t/debug/dynamic-hook.t b/t/debug/dynamic-hook.t index a14b54850e8e..094d39d00f8e 100644 --- a/t/debug/dynamic-hook.t +++ b/t/debug/dynamic-hook.t @@ -31,7 +31,8 @@ sub read_file($) { } our $debug_config = read_file("conf/debug.yaml"); -$debug_config =~ s/http:\n enable: false/http:\n enable: true/; +$debug_config =~ s/http_filter:\n enable: false/http_filter:\n enable: true/; +$debug_config =~ s/hook_conf:\n enable: false/hook_conf:\n enable: true/; run_tests(); @@ -81,15 +82,15 @@ GET /t --- response_body passed --- error_log -call require("apisix").http_access_phase() return:{} call require("apisix").http_header_filter_phase() args:{} call require("apisix").http_header_filter_phase() return:{} call require("apisix").http_body_filter_phase() args:{} call require("apisix").http_body_filter_phase() return:{} call require("apisix").http_log_phase() args:{} -call require("apisix").http_log_phase() return:{} --- no_error_log +call require("apisix").http_access_phase() return:{} call require("apisix").http_access_phase() args:{} +call require("apisix").http_log_phase() return:{} @@ -147,22 +148,22 @@ GET /t --- response_body hello world --- error_log eval -[qr/call\srequire\(\"apisix\"\).http_access_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, +[qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] --- no_error_log eval -[qr/call\srequire\(\"apisix\"\).http_access_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, +[qr/call\srequire\(\"apisix\"\).http_access_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_access_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_access_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/] +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] @@ -221,7 +222,7 @@ call require("apisix").http_log_phase() return:{} === TEST 4: plugin filter log --- debug_config -http: +http_filter: enable: true # enable or disable this feature enable_header_name: X-APISIX-Dynamic-Debug # the header name of dynamic enable hook_conf: @@ -303,11 +304,11 @@ filter(): call require("apisix.plugin").filter() return:{ === TEST 5: multiple requests, only output logs of the request with enable_header_name --- debug_config -http: +http_filter: enable: true enable_header_name: X-APISIX-Dynamic-Debug hook_conf: - enable: false + enable: true name: hook_test log_level: warn is_print_input_args: true From 7ae81f42893478d88813a8c225de3ba7ddff99c1 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Wed, 15 Sep 2021 17:18:00 +0800 Subject: [PATCH 19/25] fix code lint --- apisix/debug.lua | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index d374ff2dcf6e..29bc161d499e 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -23,7 +23,6 @@ local io = io local ngx = ngx local re_find = ngx.re.find local get_headers = ngx.req.get_headers -local get_phase = ngx.get_phase local type = type local pairs = pairs local setmetatable = setmetatable @@ -128,12 +127,14 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) local http_filter = debug_yaml.http_filter local api_ctx = ngx.ctx.api_ctx if hook_conf.is_print_input_args then - if not (http_filter and http_filter.enable) or (api_ctx and api_ctx.enable_dynamic_debug) then + if not (http_filter and http_filter.enable) + or (api_ctx and api_ctx.enable_dynamic_debug) then log[log_level]("call require(\"", file_path, "\").", fun_name, "() args:", inspect(arg)) end - if (http_filter and http_filter.enable) and (api_ctx and api_ctx.enable_dynamic_debug) then + if (http_filter and http_filter.enable) + and (api_ctx and api_ctx.enable_dynamic_debug) then log[log_level]("call require(\"", file_path, "\").", fun_name, "() args:", inspect(arg)) end @@ -141,12 +142,14 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) local ret = {self.fun_org(...)} if hook_conf.is_print_return_value then - if not (http_filter and http_filter.enable) or (api_ctx and api_ctx.enable_dynamic_debug) then + if not (http_filter and http_filter.enable) + or (api_ctx and api_ctx.enable_dynamic_debug) then log[log_level]("call require(\"", file_path, "\").", fun_name, "() return:", inspect(ret)) end - if (http_filter and http_filter.enable) and (api_ctx and api_ctx.enable_dynamic_debug) then + if (http_filter and http_filter.enable) + and (api_ctx and api_ctx.enable_dynamic_debug) then log[log_level]("call require(\"", file_path, "\").", fun_name, "() return:", inspect(ret)) end From e4d16b21d51fdfc1eeb9ddc4edbba9e68b69a975 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Fri, 17 Sep 2021 21:50:39 +0800 Subject: [PATCH 20/25] resolve code review --- apisix/debug.lua | 20 +++++++++---------- apisix/init.lua | 2 +- .../latest/architecture-design/debug-mode.md | 6 +++--- 3 files changed, 14 insertions(+), 14 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index 29bc161d499e..5df128eff8ad 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -126,15 +126,17 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) local arg = {...} local http_filter = debug_yaml.http_filter local api_ctx = ngx.ctx.api_ctx + local enable_by_hook = not (http_filter and http_filter.enable) + or (api_ctx and api_ctx.enable_dynamic_debug) + local enable_by_header_filter = (http_filter and http_filter.enable) + and (api_ctx and api_ctx.enable_dynamic_debug) if hook_conf.is_print_input_args then - if not (http_filter and http_filter.enable) - or (api_ctx and api_ctx.enable_dynamic_debug) then + if enable_by_hook then log[log_level]("call require(\"", file_path, "\").", fun_name, "() args:", inspect(arg)) end - if (http_filter and http_filter.enable) - and (api_ctx and api_ctx.enable_dynamic_debug) then + if enable_by_header_filter then log[log_level]("call require(\"", file_path, "\").", fun_name, "() args:", inspect(arg)) end @@ -142,14 +144,12 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) local ret = {self.fun_org(...)} if hook_conf.is_print_return_value then - if not (http_filter and http_filter.enable) - or (api_ctx and api_ctx.enable_dynamic_debug) then + if enable_by_hook then log[log_level]("call require(\"", file_path, "\").", fun_name, "() return:", inspect(ret)) end - if (http_filter and http_filter.enable) - and (api_ctx and api_ctx.enable_dynamic_debug) then + if enable_by_header_filter then log[log_level]("call require(\"", file_path, "\").", fun_name, "() return:", inspect(ret)) end @@ -233,13 +233,13 @@ local function check() return true end -function _M.dynamic_debug() +function _M.dynamic_debug(api_ctx) if not check() then return end if get_headers()[debug_yaml.http_filter.enable_header_name] then - ngx.ctx.api_ctx.enable_dynamic_debug = true + api_ctx.enable_dynamic_debug = true end end diff --git a/apisix/init.lua b/apisix/init.lua index defd7bd0913b..181233dbfd12 100644 --- a/apisix/init.lua +++ b/apisix/init.lua @@ -356,7 +356,7 @@ function _M.http_access_phase() core.ctx.set_vars_meta(api_ctx) - debug.dynamic_debug() + debug.dynamic_debug(api_ctx) local uri = api_ctx.var.uri if local_conf.apisix and local_conf.apisix.delete_uri_tail_slash then diff --git a/docs/en/latest/architecture-design/debug-mode.md b/docs/en/latest/architecture-design/debug-mode.md index fbbea55a2919..723827ddd81e 100644 --- a/docs/en/latest/architecture-design/debug-mode.md +++ b/docs/en/latest/architecture-design/debug-mode.md @@ -86,7 +86,7 @@ hook_phase: # Module Function List, Name: hook_phase ### Enable Advanced Debug Mode Dynamically -The advanced debug mode can be enabled dynamically by a single request and turned off automatically when the request ends. +The advanced debug mode can take effect in particular requests by dynamic rule. Example: @@ -98,10 +98,10 @@ http_filter: #END ``` -Dynamically enable advanced debugging mode, example: +Dynamically enable advanced debugging mode in a particular request like this: ```shell curl 127.0.0.1:9090/hello --header 'X-APISIX-Dynamic-Debug: foo' ``` -Notice: Dynamic advanced debug mode cannot hook the `apisix.http_access_phase` module (because the request enters the `apisix.http_access_phase` module before it determines whether advanced debug mode is dynamically enabled). +Notice: We can not only hook the `apisix.http_access_phase` module in particular requests. Because the request enters the `apisix.http_access_phase` module before it determines whether advanced debug mode is dynamically enabled. From 58ec3f94c6f6f4f4e79b4927450e3bc66123b2ec Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Fri, 17 Sep 2021 21:52:16 +0800 Subject: [PATCH 21/25] merge master --- t/debug/dynamic-hook.t | 11 +---------- 1 file changed, 1 insertion(+), 10 deletions(-) diff --git a/t/debug/dynamic-hook.t b/t/debug/dynamic-hook.t index 094d39d00f8e..38879667932f 100644 --- a/t/debug/dynamic-hook.t +++ b/t/debug/dynamic-hook.t @@ -21,16 +21,7 @@ log_level('info'); no_root_location(); no_shuffle(); -sub read_file($) { - my $infile = shift; - open my $in, $infile - or die "cannot open $infile for reading: $!"; - my $cert = do { local $/; <$in> }; - close $in; - $cert; -} - -our $debug_config = read_file("conf/debug.yaml"); +our $debug_config = t::APISIX::read_file("conf/debug.yaml"); $debug_config =~ s/http_filter:\n enable: false/http_filter:\n enable: true/; $debug_config =~ s/hook_conf:\n enable: false/hook_conf:\n enable: true/; From e47e0a4c5d207550f8ed05e359bfdfd3f2b09dde Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Fri, 17 Sep 2021 22:37:33 +0800 Subject: [PATCH 22/25] fix Ci error --- t/debug/dynamic-hook.t | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/t/debug/dynamic-hook.t b/t/debug/dynamic-hook.t index 38879667932f..1392478e5f1a 100644 --- a/t/debug/dynamic-hook.t +++ b/t/debug/dynamic-hook.t @@ -78,10 +78,10 @@ call require("apisix").http_header_filter_phase() return:{} call require("apisix").http_body_filter_phase() args:{} call require("apisix").http_body_filter_phase() return:{} call require("apisix").http_log_phase() args:{} +call require("apisix").http_log_phase() return:{} --- no_error_log call require("apisix").http_access_phase() return:{} call require("apisix").http_access_phase() args:{} -call require("apisix").http_log_phase() return:{} @@ -143,7 +143,8 @@ hello world qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] --- no_error_log eval [qr/call\srequire\(\"apisix\"\).http_access_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_access_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, @@ -153,8 +154,7 @@ qr/call\srequire\(\"apisix\"\).http_header_filter_phase\(\)\sreturn\:\{\}.*GET\s qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_body_filter_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sargs\:\{\}.*GET\s\/hello\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/, -qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello1\sHTTP\/1.1/] +qr/call\srequire\(\"apisix\"\).http_log_phase\(\)\sreturn\:\{\}.*GET\s\/hello\sHTTP\/1.1/] From 3f406258683645df2d68668d90e669cad1163fd1 Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Sat, 18 Sep 2021 10:23:07 +0800 Subject: [PATCH 23/25] fix code review --- apisix/debug.lua | 17 +++-------------- .../zh/latest/architecture-design/debug-mode.md | 2 +- 2 files changed, 4 insertions(+), 15 deletions(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index 5df128eff8ad..88b08b84c78c 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -29,7 +29,7 @@ local setmetatable = setmetatable local pcall = pcall local ipairs = ipairs local unpack = unpack -local inspect = require "inspect" +local inspect = require("inspect") local debug_yaml_path = profile:yaml_path("debug") local debug_yaml local debug_yaml_ctime @@ -127,16 +127,10 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) local http_filter = debug_yaml.http_filter local api_ctx = ngx.ctx.api_ctx local enable_by_hook = not (http_filter and http_filter.enable) - or (api_ctx and api_ctx.enable_dynamic_debug) local enable_by_header_filter = (http_filter and http_filter.enable) and (api_ctx and api_ctx.enable_dynamic_debug) if hook_conf.is_print_input_args then - if enable_by_hook then - log[log_level]("call require(\"", file_path, "\").", fun_name, - "() args:", inspect(arg)) - end - - if enable_by_header_filter then + if enable_by_hook or enable_by_header_filter then log[log_level]("call require(\"", file_path, "\").", fun_name, "() args:", inspect(arg)) end @@ -144,12 +138,7 @@ local function apple_new_fun(module, fun_name, file_path, hook_conf) local ret = {self.fun_org(...)} if hook_conf.is_print_return_value then - if enable_by_hook then - log[log_level]("call require(\"", file_path, "\").", fun_name, - "() return:", inspect(ret)) - end - - if enable_by_header_filter then + if enable_by_hook or enable_by_header_filter then log[log_level]("call require(\"", file_path, "\").", fun_name, "() return:", inspect(ret)) end diff --git a/docs/zh/latest/architecture-design/debug-mode.md b/docs/zh/latest/architecture-design/debug-mode.md index da55c1a14a04..a4e7692d306a 100644 --- a/docs/zh/latest/architecture-design/debug-mode.md +++ b/docs/zh/latest/architecture-design/debug-mode.md @@ -88,7 +88,7 @@ hook_phase: # 模块函数列表，名字：hook_phase ### 动态高级调试模式 -动态高级调试模式是基于高级调试模式，可以由单个请求动态开启高级调试模式，请求结束后自动关闭。设置 `conf/debug.yaml` 中的选项。 +动态高级调试模式是基于高级调试模式，可以由单个请求动态开启高级调试模式。设置 `conf/debug.yaml` 中的选项。 示例： From be61095c89aadbd943ebf46d8e1206f843c9d0bd Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Sat, 18 Sep 2021 14:55:08 +0800 Subject: [PATCH 24/25] fix code review --- apisix/debug.lua | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/apisix/debug.lua b/apisix/debug.lua index 88b08b84c78c..363aee172e4f 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -19,6 +19,7 @@ local yaml = require("tinyyaml") local log = require("apisix.core.log") local profile = require("apisix.core.profile") local lfs = require("lfs") +local inspect = require("inspect") local io = io local ngx = ngx local re_find = ngx.re.find @@ -29,7 +30,6 @@ local setmetatable = setmetatable local pcall = pcall local ipairs = ipairs local unpack = unpack -local inspect = require("inspect") local debug_yaml_path = profile:yaml_path("debug") local debug_yaml local debug_yaml_ctime From 46f19bee266f9aab8005ddb45fb2fc87dd8634ed Mon Sep 17 00:00:00 2001 From: tzssangglass Date: Tue, 21 Sep 2021 20:12:25 +0800 Subject: [PATCH 25/25] resolve code review --- docs/en/latest/architecture-design/debug-mode.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/en/latest/architecture-design/debug-mode.md b/docs/en/latest/architecture-design/debug-mode.md index 723827ddd81e..5c66343c570d 100644 --- a/docs/en/latest/architecture-design/debug-mode.md +++ b/docs/en/latest/architecture-design/debug-mode.md @@ -104,4 +104,4 @@ Dynamically enable advanced debugging mode in a particular request like this: curl 127.0.0.1:9090/hello --header 'X-APISIX-Dynamic-Debug: foo' ``` -Notice: We can not only hook the `apisix.http_access_phase` module in particular requests. Because the request enters the `apisix.http_access_phase` module before it determines whether advanced debug mode is dynamically enabled. +Notice: We can not hook the `apisix.http_access_phase` module for particular requests, since whether the advanced debug mode is enabled is determined after these requests enter such phase.