fix(tracing): trace hook error out when see nil

CHANGELOG.md

@@ -95,6 +95,8 @@
   [#10352](https://github.com/Kong/kong/pull/10352)
 - Fix an issue where validation to regex routes may be skipped when the old-fashioned config is used for DB-less Kong.
   [#10348](https://github.com/Kong/kong/pull/10348)
+- Fix and issue where tracing may cause unexpected behavior.
+  [#10364](https://github.com/Kong/kong/pull/10364)
 - Fix an issue where balancer passive healthcheck would use wrong status code when kong changes status code
   from upstream in `header_filter` phase.
   [#10325](https://github.com/Kong/kong/pull/10325)

kong/pdk/tracing.lua

@@ -32,6 +32,8 @@ local ffi_str = ffi.string
 local ffi_time_unix_nano = utils.time_ns
 local tablepool_fetch = tablepool.fetch
 local tablepool_release = tablepool.release
+local ngx_log = ngx.log
+local ngx_ERR = ngx.ERR
 
 local NOOP = function() end
 
@@ -253,13 +255,18 @@ end
 -- span:set_attribute("net.peer.port", 443)
 -- span:set_attribute("exception.escaped", true)
 function span_mt:set_attribute(key, value)
+  -- key is decided by the programmer, so if it is not a string, we should
+  -- error out.
   if type(key) ~= "string" then
     error("invalid key", 2)
   end
 
   local vtyp = type(value)
   if vtyp ~= "string" and vtyp ~= "number" and vtyp ~= "boolean" then
-    error("invalid value", 2)
+    -- we should not error out here, as most of the caller does not catch
+    -- errors, and they are hooking to core facilities, which may cause
+    -- unexpected behavior.
+    ngx_log(ngx_ERR, debug.traceback("invalid span attribute value type: " .. vtyp, 2))
   end
 
   if self.attributes == nil then

spec/01-unit/26-tracing/01-tracer_pdk_spec.lua

@@ -1,14 +1,54 @@
 require "spec.helpers" -- initializes 'kong' global for tracer
+local match = require("luassert.match")
+
+--- hook ngx.log to a spy for unit test
+--- usage: local log_spy = hook_log_spy() -- hook ngx.log to a spy
+---        -- do stuff
+---        assert.spy(log_spy).was_called_with(ngx.ERR, "some error")
+---        -- unhook
+---        unhook_log_spy()
+--- note that all messages arguments are concatenated together.
+--- this hook slows down the test execution by a lot so only use if necessary.
+-- @function hook_log_spy
+-- @return log_spy the spy
+local function hook_log_spy()
+  local log_spy = spy(function() end)
+  local level, msg
+  -- the only reliable way to hook into ngx.log
+  -- is to use debug.sethook as ngx.log is always
+  -- localized and even reload the module does not work
+  debug.sethook(function()
+    if debug.getinfo(2, 'f').func == ngx.log then
+      level, msg = select(2, debug.getlocal(2, 1)),
+      table.concat {
+        select(2, debug.getlocal(2, 2)),
+        select(2, debug.getlocal(2, 3)),
+        select(2, debug.getlocal(2, 4)),
+        select(2, debug.getlocal(2, 5)),
+        select(2, debug.getlocal(2, 6)),
+      }
+      print(msg)
+      log_spy(level, msg)
+    end
+  end, "c", 1)
+  return log_spy
+end
+
+local unhook_log_spy = debug.sethook
 
 describe("Tracer PDK", function()
   local ok, err, _
+  local log_spy
 
   lazy_setup(function()
     local kong_global = require "kong.global"
     _G.kong = kong_global.new()
     kong_global.init_pdk(kong)
+    log_spy = hook_log_spy()
   end)
 
+  lazy_teardown(unhook_log_spy)
+
   describe("initialize tracer", function()
 
     it("tracer instance created", function ()
@@ -138,16 +178,21 @@ describe("Tracer PDK", function()
 
     it("fails set_attribute", function ()
       local span = c_tracer.start_span("meow")
-      assert.error(function() span:set_attribute("key1") end)
-      assert.error(function() span:set_attribute("key1", function() end) end)
+
+      span:set_attribute("key1")
+      assert.spy(log_spy).was_called_with(ngx.ERR, match.is_string())
+
+      span:set_attribute("key1", function() end)
+      assert.spy(log_spy).was_called_with(ngx.ERR, match.is_string())
+
       assert.error(function() span:set_attribute(123, 123) end)
     end)
 
     it("fails add_event", function ()
       local span = c_tracer.start_span("meow")
-      assert.error(function() span:set_attribute("key1") end)
-      assert.error(function() span:set_attribute("key1", function() end) end)
-      assert.error(function() span:set_attribute(123, 123) end)
+      assert.error(function() span:add_event("key1", 123) end)
+      assert.error(function() span:add_event("key1", function() end) end)
+      assert.error(function() span:add_event(123, {}) end)
     end)
 
     it("child spans", function ()