feat(tracing): per request debugging

changelog/unreleased/kong/per_reqeuest_deubgging.yml

@@ -0,0 +1,3 @@
+message: Support observing the time consumed by some components in the given request.
+type: feature
+scope: Core

kong-3.5.0-0.rockspec

@@ -531,5 +531,16 @@ build = {
 
     ["kong.tracing.instrumentation"] = "kong/tracing/instrumentation.lua",
     ["kong.tracing.propagation"] = "kong/tracing/propagation.lua",
+
+    ["kong.timing"] = "kong/timing/init.lua",
+    ["kong.timing.context"] = "kong/timing/context.lua",
+    ["kong.timing.hooks"] = "kong/timing/hooks/init.lua",
+    ["kong.timing.hooks.dns"] = "kong/timing/hooks/dns.lua",
+    ["kong.timing.hooks.http"] = "kong/timing/hooks/http.lua",
+    ["kong.timing.hooks.redis"] = "kong/timing/hooks/redis.lua",
+    ["kong.timing.hooks.socket"] = "kong/timing/hooks/socket.lua",
+
+    ["kong.dynamic_hook"] = "kong/dynamic_hook/init.lua",
+    ["kong.dynamic_hook.wrap_function_gen"] = "kong/dynamic_hook/wrap_function_gen.lua",
   }
 }

kong/conf_loader/init.lua

@@ -597,6 +597,9 @@ local CONF_PARSERS = {
   admin_gui_url = {typ = "string"},
   admin_gui_path = {typ = "string"},
   admin_gui_api_url = {typ = "string"},
+
+  request_debug = { typ = "boolean" },
+  request_debug_token = { typ = "string" },
 }
 
 

kong/constants.lua

@@ -245,6 +245,9 @@ local constants = {
   DYN_LOG_LEVEL_TIMEOUT_AT_KEY = "kong:dyn_log_level_timeout_at",
 
   ADMIN_GUI_KCONFIG_CACHE_KEY = "admin:gui:kconfig",
+
+  REQUEST_DEBUG_TOKEN_FILE = ".request_debug_token",
+  REQUEST_DEBUG_LOG_PREFIX = "[request-debug]",
 }
 
 for _, v in ipairs(constants.CLUSTERING_SYNC_STATUS) do

kong/dynamic_hook/init.lua

@@ -0,0 +1,127 @@
+local warp_function_gen = require("kong.dynamic_hook.wrap_function_gen")
+
+local ngx               = ngx
+
+local _M                = {
+  TYPE = {
+    BEFORE = 1,
+    AFTER  = 2,
+    BEFORE_MUT = 3,
+    AFTER_MUT  = 4,
+  },
+}
+
+local pcall             = pcall
+
+local non_function_hooks = {
+--[[
+  [group_name] = {
+    [hook_name] = <function>,
+    ...
+  },
+  ...
+--]]
+}
+
+local always_enabled_groups = {}
+
+local wrap_functions = {
+  [0] = warp_function_gen.generate_wrap_function(0),
+  [1] = warp_function_gen.generate_wrap_function(1),
+  [2] = warp_function_gen.generate_wrap_function(2),
+  [3] = warp_function_gen.generate_wrap_function(3),
+  [4] = warp_function_gen.generate_wrap_function(4),
+  [5] = warp_function_gen.generate_wrap_function(5),
+  [6] = warp_function_gen.generate_wrap_function(6),
+  [7] = warp_function_gen.generate_wrap_function(7),
+  [8] = warp_function_gen.generate_wrap_function(8),
+  ["varargs"] = warp_function_gen.generate_wrap_function("varargs"),
+}
+
+
+function _M.hook_function(group_name, parent, child_key, max_args, handlers)
+  assert(type(parent) == "table", "parent must be a table")
+  assert(type(child_key) == "string", "child_key must be a string")
+
+  if type(max_args) == "string" then
+    assert(max_args == "varargs", "max_args must be a number or \"varargs\"")
+    assert(handlers.before_mut == nil, "before_mut is not supported for varargs functions")
+
+  else
+    assert(type(max_args) == "number", "max_args must be a number or \"varargs\"")
+    assert(max_args >= 0 and max_args <= 8, "max_args must be >= 0")
+  end
+
+  local old_func = parent[child_key]
+  assert(type(old_func) == "function", "parent[" .. child_key .. "] must be a function")
+
+  parent[child_key] = wrap_functions[max_args](always_enabled_groups, group_name, old_func, handlers)
+end
+
+
+function _M.hook(group_name, hook_name, handler)
+  assert(type(group_name) == "string", "group_name must be a string")
+  assert(type(hook_name) == "string", "hook_name must be a string")
+  assert(type(handler) == "function", "handler must be a function")
+
+  local hooks = non_function_hooks[group_name]
+  if not hooks then
+    hooks = {}
+    non_function_hooks[group_name] = hooks
+  end
+
+  hooks[hook_name] = handler
+end
+
+
+function _M.run_hooks(group_name, hook_name, ...)
+  if not always_enabled_groups[group_name] then
+    local dynamic_hook = ngx.ctx.dynamic_hook
+    if not dynamic_hook then
+      return
+    end
+
+    local enabled_groups = dynamic_hook.enabled_groups
+    if not enabled_groups[group_name] then
+      return
+    end
+  end
+
+  local hooks = non_function_hooks[group_name]
+  if not hooks then
+    return
+  end
+
+  local handler = hooks[hook_name]
+  if not handler then
+    return
+  end
+
+  local ok, err = pcall(handler, ...)
+  if not ok then
+    ngx.log(ngx.WARN,
+            string.format("failed to run dynamic hook %s.%s: %s",
+                          group_name, hook_name, err))
+  end
+end
+
+
+function _M.enable_on_this_request(group_name)
+  local info = ngx.ctx.dynamic_hook
+  if not info then
+    info = {
+      enabled_groups = {},
+    }
+    ngx.ctx.dynamic_hook = info
+  end
+
+  info.enabled_groups[group_name] = true
+end
+
+
+function _M.always_enable(group_name)
+  always_enabled_groups[group_name] = true
+end
+
+
+return _M

kong/dynamic_hook/wrap_function_gen.lua

@@ -0,0 +1,223 @@
+local ngx_get_phase = ngx.get_phase
+
+local TEMPLATE = [[
+  return function(always_enabled_groups, group_name, original_func, handlers)
+    -- we cannot access upvalue here as this function is generated
+    local ngx_get_phase = ngx.get_phase
+
+    return function(%s)
+      if not always_enabled_groups[group_name] then
+        local phase = ngx_get_phase()
+        if phase == "init" or phase == "init_worker" then
+          return original_func(%s)
+        end
+        local dynamic_hook = ngx.ctx.dynamic_hook
+        if not dynamic_hook then
+          return original_func(%s)
+        end
+
+        local enabled_groups = dynamic_hook.enabled_groups
+        if not enabled_groups[group_name] then
+          return original_func(%s)
+        end
+      end
+
+      if handlers.before_mut then
+        local ok
+        ok, %s = pcall(handlers.before_mut, %s)
+        if not ok then
+          ngx.log(ngx.WARN,
+                  string.format("failed to run before_mut hook of %%s: %%s",
+                              group_name, a0))
+        end
+      end
+
+      if handlers.befores then
+        for _, func in ipairs(handlers.befores) do
+          local ok, err = pcall(func, %s)
+          if not ok then
+            ngx.log(ngx.WARN,
+                    string.format("failed to run before hook of %%s: %%s",
+                                  group_name, err))
+          end
+        end
+      end
+
+      local r0, r1, r2, r3, r4, r5, r6, r7 = original_func(%s)
+
+      if handlers.after_mut then
+        local ok, err = pcall(handlers.after_mut, r0, r1, r2, r3, r4, r5, r6, r7)
+        if not ok then
+          ngx.log(ngx.WARN,
+                  string.format("failed to run after_mut hook of %%s: %%s",
+                                group_name, err))
+        end
+      end
+
+      if handlers.afters then
+        for _, func in ipairs(handlers.afters) do
+          local ok, err = pcall(func, r0, r1, r2, r3, r4, r5, r6, r7)
+          if not ok then
+            ngx.log(ngx.WARN,
+                    string.format("failed to run after hook of %%s: %%s",
+                                  group_name, err))
+          end
+        end
+      end
+
+      return r0, r1, r2, r3, r4, r5, r6, r7
+    end
+  end
+]]
+
+
+local _M = {}
+
+
+local function warp_function_0(always_enabled_groups, group_name, original_func, handlers)
+  return function()
+    if not always_enabled_groups[group_name] then
+      local phase = ngx_get_phase()
+      if phase == "init" or phase == "init_worker" then
+        return original_func()
+      end
+
+      local dynamic_hook = ngx.ctx.dynamic_hook
+      if not dynamic_hook then
+        return original_func()
+      end
+
+      local enabled_groups = dynamic_hook.enabled_groups
+      if not enabled_groups[group_name] then
+        return original_func()
+      end
+    end
+
+    if handlers.before_mut then
+      local ok, err = pcall(handlers.before_mut)
+      if not ok then
+        ngx.log(ngx.WARN,
+                string.format("failed to run before_mut hook of %s: %s",
+                              group_name, err))
+      end
+    end
+
+    if handlers.befores then
+      for _, func in ipairs(handlers.befores) do
+        local ok, err = pcall(func)
+        if not ok then
+          ngx.log(ngx.WARN,
+                  string.format("failed to run before hook of %s: %s",
+                                group_name, err))
+        end
+      end
+    end
+
+    local r0, r1, r2, r3, r4, r5, r6, r7 = original_func()
+
+    if handlers.after_mut then
+      local ok, err = pcall(handlers.after_mut, r0, r1, r2, r3, r4, r5, r6, r7)
+      if not ok then
+        ngx.log(ngx.WARN,
+                string.format("failed to run after_mut hook of %s: %s",
+                              group_name, err))
+      end
+    end
+
+    if handlers.afters then
+      for _, func in ipairs(handlers.afters) do
+        local ok, err = pcall(func, r0, r1, r2, r3, r4, r5, r6, r7)
+        if not ok then
+          ngx.log(ngx.WARN,
+                  string.format("failed to run after hook of %s: %s",
+                                group_name, err))
+        end
+      end
+    end
+
+    return r0, r1, r2, r3, r4, r5, r6, r7
+  end
+end
+
+
+local function wrap_function_varargs(always_enabled_groups, group_name, original_func, handlers)
+  return function(...)
+    if not always_enabled_groups[group_name] then
+      local phase = ngx_get_phase()
+      if phase == "init" or phase == "init_worker" then
+        return original_func(...)
+      end
+
+      local dynamic_hook = ngx.ctx.dynamic_hook
+      if not dynamic_hook then
+        return original_func(...)
+      end
+
+      local enabled_groups = dynamic_hook.enabled_groups
+      if not enabled_groups[group_name] then
+        return original_func(...)
+      end
+    end
+
+    -- before_mut is not supported for varargs functions
+
+    if handlers.befores then
+      for _, func in ipairs(handlers.befores) do
+        local ok, err = pcall(func, ...)
+        if not ok then
+          ngx.log(ngx.WARN,
+                  string.format("failed to run before hook of %s: %s",
+                                group_name, err))
+        end
+      end
+    end
+
+    local r0, r1, r2, r3, r4, r5, r6, r7 = original_func(...)
+
+    if handlers.after_mut then
+      local ok, err = pcall(handlers.after_mut, r0, r1, r2, r3, r4, r5, r6, r7)
+      if not ok then
+        ngx.log(ngx.WARN,
+                string.format("failed to run after_mut hook of %s: %s",
+                              group_name, err))
+      end
+    end
+
+    if handlers.afters then
+      for _, func in ipairs(handlers.afters) do
+        local ok, err = pcall(func, r0, r1, r2, r3, r4, r5, r6, r7)
+        if not ok then
+          ngx.log(ngx.WARN,
+                  string.format("failed to run after hook of %s: %s",
+                                group_name, err))
+        end
+      end
+    end
+
+    return r0, r1, r2, r3, r4, r5, r6, r7
+  end
+end
+
+
+function _M.generate_wrap_function(max_args)
+  if max_args == 0 then
+    return warp_function_0
+  end
+
+  if max_args == "varargs" then
+    return wrap_function_varargs
+  end
+
+  local args = "a0" -- the 1st arg must be named as "a0" as
+                    -- it will be used in the error log
+
+  for i = 1, max_args - 1 do
+    args = args .. ", a" .. i
+  end
+
+  local func = assert(loadstring(string.format(TEMPLATE, args, args, args, args, args, args, args, args)))()
+  assert(type(func) == "function", "failed to generate wrap function: " .. tostring(func))
+  return func
+end
+
+return _M