diff --git a/apisix/debug.lua b/apisix/debug.lua index f07aff553b44..363aee172e4f 100644 --- a/apisix/debug.lua +++ b/apisix/debug.lua @@ -17,12 +17,13 @@ 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 lfs = require("lfs") +local inspect = require("inspect") local io = io local ngx = ngx local re_find = ngx.re.find +local get_headers = ngx.req.get_headers local type = type local pairs = pairs local setmetatable = setmetatable @@ -123,15 +124,24 @@ 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 + local enable_by_hook = not (http_filter and http_filter.enable) + 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 - log[log_level]("call require(\"", file_path, "\").", fun_name, - "() args:", json.delay_encode(arg, true)) + if enable_by_hook or enable_by_header_filter 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 - log[log_level]("call require(\"", file_path, "\").", fun_name, - "() return:", json.delay_encode(ret, true)) + if enable_by_hook or enable_by_header_filter then + log[log_level]("call require(\"", file_path, "\").", fun_name, + "() return:", inspect(ret)) + end end return unpack(ret) end @@ -199,6 +209,30 @@ local function sync_debug_status(premature) end +local function check() + if not debug_yaml or not debug_yaml.http_filter then + return false + end + + 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 + + return true +end + +function _M.dynamic_debug(api_ctx) + if not check() then + return + end + + if get_headers()[debug_yaml.http_filter.enable_header_name] then + api_ctx.enable_dynamic_debug = true + end +end + + function _M.enable_debug() if not debug_yaml or not debug_yaml.basic then return false diff --git a/apisix/init.lua b/apisix/init.lua index 1a3358a4b99b..181233dbfd12 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 @@ -355,6 +356,8 @@ function _M.http_access_phase() core.ctx.set_vars_meta(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 if str_byte(uri, #uri) == str_byte("/") then diff --git a/conf/debug.yaml b/conf/debug.yaml index 3d53486e9e6b..23c8d51a4672 100644 --- a/conf/debug.yaml +++ b/conf/debug.yaml @@ -16,6 +16,9 @@ # basic: enable: false +http_filter: + 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 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 1d0ad8c3223d..5c66343c570d 100644 --- a/docs/en/latest/architecture-design/debug-mode.md +++ b/docs/en/latest/architecture-design/debug-mode.md @@ -83,3 +83,25 @@ hook_phase: # Module Function List, Name: hook_phase - http_log_phase #END ``` + +### Enable Advanced Debug Mode Dynamically + +The advanced debug mode can take effect in particular requests by dynamic rule. + +Example: + +```yaml +http_filter: + enable: true # Enable/Disable Advanced Debug Mode Dynamically + enable_header_name: X-APISIX-Dynamic-Debug # Trace for the request with this header +...... +#END +``` + +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: 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. diff --git a/docs/zh/latest/architecture-design/debug-mode.md b/docs/zh/latest/architecture-design/debug-mode.md index 0e647d843641..a4e7692d306a 100644 --- a/docs/zh/latest/architecture-design/debug-mode.md +++ b/docs/zh/latest/architecture-design/debug-mode.md @@ -85,3 +85,25 @@ hook_phase: # 模块函数列表,名字:hook_phase - http_log_phase #END ``` + +### 动态高级调试模式 + +动态高级调试模式是基于高级调试模式,可以由单个请求动态开启高级调试模式。设置 `conf/debug.yaml` 中的选项。 + +示例: + +```yaml +http_filter: + enable: 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/rockspec/apisix-master-0.rockspec b/rockspec/apisix-master-0.rockspec index 597915c5722d..79a096696e97 100644 --- a/rockspec/apisix-master-0.rockspec +++ b/rockspec/apisix-master-0.rockspec @@ -70,6 +70,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/debug/dynamic-hook.t b/t/debug/dynamic-hook.t new file mode 100644 index 000000000000..1392478e5f1a --- /dev/null +++ b/t/debug/dynamic-hook.t @@ -0,0 +1,371 @@ +# +# 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(); + +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/; + +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('/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 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: 2 +--- response_body +passed +--- error_log +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:{} + + + +=== 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('/apisix/admin/routes/1', + ngx.HTTP_PUT, + [[{ + "uris": ["/hello","/hello1"], + "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 http = require "resty.http" + local httpc = http.new() + local headers = {} + 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 + + 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.print(res.body) + } + } +--- request +GET /t +--- wait: 2 +--- response_body +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_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_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/] + + + +=== 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", + "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 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: 2 +--- response_body +passed +--- no_error_log +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: plugin filter log +--- debug_config +http_filter: + 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('/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" + }, + "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 headers = {} + headers["X-APISIX-Dynamic-Debug"] = "" -- has the header name of dynamic debug + local code, body = t('/hello', + ngx.HTTP_GET, + "", + nil, + headers + ) + + ngx.sleep(1.1) + ngx.status = code + ngx.say(body) + } + } +--- request +GET /t +--- wait: 2 +--- response_body +passed +--- no_error_log +[error] +--- 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_filter: + enable: true + enable_header_name: X-APISIX-Dynamic-Debug +hook_conf: + enable: true + 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 +--- wait: 2 +--- 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/ diff --git a/t/debug/hook.t b/t/debug/hook.t index 68fcdb63380f..5afac49ce589 100644 --- a/t/debug/hook.t +++ b/t/debug/hook.t @@ -125,5 +125,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:{ +filter(): call require("apisix.plugin").filter() return:{