feat(tracing): per request debugging

kong-3.5.0-0.rockspec

@@ -530,5 +530,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,8 @@ 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"
 }
 
 for _, v in ipairs(constants.CLUSTERING_SYNC_STATUS) do

kong/dynamic_hook/init.lua

@@ -0,0 +1,123 @@
+local warp_function_gen = require("kong.dynamic_hook.wrap_function_gen")
+
+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, "error in hook: ", err)
+  end
+end
+
+
+function _M.enable_on_this_request(group_name)
+  local info = ngx.ctx.dynamic_hook
+  if info == nil 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,181 @@
+local TEMPLATE = [[
+  return function(always_enabled_groups, group_name, original_func, handlers)
+    return function(%s)
+      if not always_enabled_groups[group_name] then
+        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, "error in before_mut hook: ", 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, "error in before hook: ", err)
+          end
+        end
+      end
+      
+      ngx.log(ngx.ERR, debug.traceback())
+      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, "error in after_mut hook: ", 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, "error in after hook: ", 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 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, "error in before_mut hook: ", 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, "error in before hook: ", 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, "error in after_mut hook: ", 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, "error in after hook: ", 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 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.befores then
+      for _, func in ipairs(handlers.befores) do
+        local ok, err = pcall(func, ...)
+        if not ok then
+          ngx.log(ngx.WARN, "error in before hook: ", 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, "error in after_mut hook: ", 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, "error in after hook: ", 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 = 2, max_args do
+    args = args .. ", a" .. i
+  end
+
+  local func = assert(loadstring(string.format(TEMPLATE, args, args, args, args, args, args, args)))()
+  assert(type(func) == "function", "failed to generate wrap function: " .. tostring(func))
+  return func
+end
+
+return _M

kong/global.lua

@@ -289,4 +289,9 @@ function _GLOBAL.init_core_cache(kong_config, cluster_events, worker_events)
 end
 
 
+function _GLOBAL.init_timing()
+  return require("kong.timing")
+end
+
+
 return _GLOBAL

kong/globalpatches.lua

@@ -17,7 +17,7 @@ return function(options)
 
   local cjson = require("cjson.safe")
   cjson.encode_sparse_array(nil, nil, 2^15)
-  
+
   local pb = require "pb"
 
   -- let pb decode arrays to table cjson.empty_array_mt metatable
@@ -508,8 +508,6 @@ return function(options)
     end
   end
 
-
-
   do -- cosockets connect patch for dns resolution for: cli, rbusted and OpenResty
     local sub = string.sub
 
@@ -583,6 +581,11 @@ return function(options)
       return sock
     end
 
+    if not options.cli and not options.rbusted then
+      local timing = require "kong.timing"
+      timing.register_hooks()
+    end
+
     -- STEP 5: load code that should be using the patched versions, if any (because of dependency chain)
     do
       local client = package.loaded["kong.resty.dns.client"]

kong/hooks.lua

@@ -8,6 +8,7 @@ local ipairs = ipairs
 local pack = table.pack
 local unpack = table.unpack
 local insert = table.insert
+local EMPTY = require("pl.tablex").readonly({})
 
 
 local function wrap_hook(f)
@@ -57,7 +58,7 @@ function _M.run_hook(name, ...)
 
   local acc
 
-  for _, f in ipairs(hooks[name] or {}) do
+  for _, f in ipairs(hooks[name] or EMPTY) do
     acc = f(acc, ...)
   end