fix(tracing): span start/end time precision (#11484) (#11556)

* fix(tracing): span start/end time precision

Ensure the span lifetime is consistent with the hierarchy
by using the same time source for the root span's end time as the
balancer span.

Before this fix, an approximation (causing a precision error) could
result in the root span to end before its children.

* docs(changelog): add issue

Co-authored-by: Xumin <[email protected]>

---------

Co-authored-by: Xumin <[email protected]>
(cherry picked from commit 37a17eb)

Co-authored-by: Samuele <[email protected]>

CHANGELOG/unreleased/kong/11484.yaml

@@ -0,0 +1,9 @@
+message: "Tracing: fix an issue that resulted in some parent spans to end before their children due to different precision of their timestamps"
+type: bugfix
+scope: PDK
+prs:
+  - 11484
+jiras:
+  - "KAG-2336"
+issues:
+  - 11294

kong/init.lua

@@ -1503,6 +1503,7 @@ function Kong.log()
   local ctx = ngx.ctx
   if not ctx.KONG_LOG_START then
     ctx.KONG_LOG_START = now() * 1000
+    ctx.KONG_LOG_START_NS = time_ns()
     if is_stream_module then
       if not ctx.KONG_PROCESSING_START then
         ctx.KONG_PROCESSING_START = start_time() * 1000
@@ -1571,6 +1572,7 @@ function Kong.log()
 
       if ctx.KONG_BODY_FILTER_START and not ctx.KONG_BODY_FILTER_ENDED_AT then
         ctx.KONG_BODY_FILTER_ENDED_AT = ctx.KONG_LOG_START
+        ctx.KONG_BODY_FILTER_ENDED_AT_NS = ctx.KONG_LOG_START_NS
         ctx.KONG_BODY_FILTER_TIME = ctx.KONG_BODY_FILTER_ENDED_AT -
                                     ctx.KONG_BODY_FILTER_START
       end

kong/tracing/instrumentation.lua

@@ -313,8 +313,7 @@ function _M.runloop_log_before(ctx)
   local active_span = tracer.active_span()
   -- check root span type to avoid encounter error
   if active_span and type(active_span.finish) == "function" then
-    local end_time = ctx.KONG_BODY_FILTER_ENDED_AT
-                  and ctx.KONG_BODY_FILTER_ENDED_AT * 1e6
+    local end_time = ctx.KONG_BODY_FILTER_ENDED_AT_NS
     active_span:finish(end_time)
   end
 end

spec/02-integration/14-tracing/03-tracer-pdk_spec.lua

@@ -7,6 +7,14 @@ local TCP_PORT = helpers.get_available_port()
 local tcp_trace_plugin_name = "tcp-trace-exporter"
 
 
+local function get_parent(span, spans)
+  for _, s in ipairs(spans) do
+    if s.span_id == span.parent_id then
+      return s
+    end
+  end
+end
+
 for _, strategy in helpers.each_strategy() do
   local proxy_client
 
@@ -77,5 +85,39 @@ for _, strategy in helpers.each_strategy() do
         end
       end)
     end)
+
+    describe("spans start/end times are consistent with their hierarchy", function ()
+      lazy_setup(function()
+        setup_instrumentations("all", false, 1)
+      end)
+
+      lazy_teardown(function()
+        helpers.stop_kong()
+      end)
+
+      it("sets child lifespan within parent's lifespan", function ()
+        for _ = 1, 100 do
+          local thread = helpers.tcp_server(TCP_PORT)
+          local r = assert(proxy_client:send {
+            method  = "GET",
+            path    = "/",
+          })
+          assert.res_status(200, r)
+
+          local ok, res = thread:join()
+          assert.True(ok)
+          assert.is_string(res)
+
+          local spans = cjson.decode(res)
+          for i = 2, #spans do -- skip the root span (no parent)
+            local span = spans[i]
+            local parent = get_parent(span, spans)
+            assert.is_not_nil(parent)
+            assert.True(span.start_time_ns >= parent.start_time_ns)
+            assert.True(span.end_time_ns <= parent.end_time_ns)
+          end
+        end
+      end)
+    end)
   end)
 end