--- -- Tracer module -- -- Application-level tracing for Kong. -- -- @module kong.tracing local require = require local ffi = require "ffi" local tablepool = require "tablepool" local new_tab = require "table.new" local phase_checker = require "kong.pdk.private.phases" local tracing_context = require "kong.observability.tracing.tracing_context" local ngx = ngx local type = type local error = error local ipairs = ipairs local tostring = tostring local setmetatable = setmetatable local getmetatable = getmetatable local rand_bytes = require("kong.tools.rand").get_rand_bytes local check_phase = phase_checker.check local PHASES = phase_checker.phases local ffi_cast = ffi.cast local ffi_str = ffi.string local ffi_time_unix_nano = require("kong.tools.time").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 local POOL_SPAN = "KONG_SPAN" local POOL_SPAN_STORAGE = "KONG_SPAN_STORAGE" local POOL_ATTRIBUTES = "KONG_SPAN_ATTRIBUTES" local POOL_EVENTS = "KONG_SPAN_EVENTS" -- must be power of 2 local SAMPLING_BYTE = 8 local SAMPLING_BITS = 8 * SAMPLING_BYTE local BOUND_MAX = math.pow(2, SAMPLING_BITS) local SAMPLING_UINT_PTR_TYPE = "uint" .. SAMPLING_BITS .. "_t*" local TOO_SHORT_MESSAGE = "sampling needs trace ID to be longer than " .. SAMPLING_BYTE .. " bytes to work" local SPAN_KIND = { UNSPECIFIED = 0, INTERNAL = 1, SERVER = 2, CLIENT = 3, PRODUCER = 4, CONSUMER = 5, } --- Generate trace ID local function generate_trace_id() return rand_bytes(16) end --- Generate span ID local function generate_span_id() return rand_bytes(8) end -- Fractions >= 1 will always sample. Fractions < 0 are treated as zero. -- spec: https://github.com/c24t/opentelemetry-specification/blob/3b3d321865cf46364bdfb292c179b6444dc96bf9/specification/sdk-tracing.md#probability-sampler-algorithm local function get_trace_id_based_sampler(options_sampling_rate) return function(trace_id, sampling_rate) sampling_rate = sampling_rate or options_sampling_rate if type(sampling_rate) ~= "number" then return nil, "invalid fraction" end -- always on sampler if sampling_rate >= 1 then return true end -- always off sampler if sampling_rate <= 0 then return false end -- probability sampler local bound = sampling_rate * BOUND_MAX if #trace_id < SAMPLING_BYTE then return nil, TOO_SHORT_MESSAGE end local truncated = ffi_cast(SAMPLING_UINT_PTR_TYPE, ffi_str(trace_id, SAMPLING_BYTE))[0] return truncated < bound end end -- @class span : table -- --- Trace Context. Those IDs are all represented as bytes, and the length may vary. -- We try best to preserve as much information as possible from the tracing context. -- @field trace_id bytes auto generated 16 bytes ID if not designated -- @field span_id bytes -- @field parent_span_id bytes -- --- Timing. All times are in nanoseconds. -- @field start_time_ns number -- @field end_time_ns number -- --- Scopes and names. Defines what the span is about. -- TODO: service should be retrieved from kong service instead of from plugin instances. It should be the same for spans from a single request. -- service name/top level scope is defined by plugin instances. -- @field name string type of the span. Should be of low cardinality. Good examples are "proxy", "DNS query", "database query". Approximately operation name of DataDog. -- resource_name of Datadog is built from attirbutes. -- --- Other fields -- @field should_sample boolean whether the span should be sampled -- @field kind number TODO: Should we remove this field? It's used by OTEL and zipkin. Maybe move this to impl_specific. -- @field attributes table extra information about the span. Attribute of OTEL or meta of Datadog. -- TODO: @field impl_specific table implementation specific fields. For example, impl_specific.datadog is used by Datadog tracer. -- TODO: @field events table list of events. -- --- Internal fields -- @field tracer table -- @field parent table local span_mt = {} span_mt.__index = span_mt -- Noop Span local noop_span = {} -- Using static function instead of metatable for better performance noop_span.is_recording = false noop_span.finish = NOOP noop_span.set_attribute = NOOP noop_span.add_event = NOOP noop_span.record_error = NOOP noop_span.set_status = NOOP noop_span.each_baggage_item = function() return NOOP end setmetatable(noop_span, { -- Avoid noop span table being modifed __newindex = NOOP, }) local function validate_span_options(options) if options ~= nil then if type(options) ~= "table" then error("invalid options type", 2) end if options.start_time_ns ~= nil and type(options.start_time_ns) ~= "number" then error("invalid start time", 2) end if options.span_kind ~= nil and type(options.span_kind) ~= "number" then error("invalid start kind", 2) end if options.should_sample ~= nil and type(options.should_sample) ~= "boolean" then error("invalid sampled", 2) end if options.attributes ~= nil and type(options.attributes) ~= "table" then error("invalid attributes", 2) end end end local function create_span(tracer, options) validate_span_options(options) options = options or {} local span = tablepool_fetch(POOL_SPAN, 0, 12) span.parent = options.parent or tracer and tracer.active_span() local trace_id = span.parent and span.parent.trace_id or options.trace_id or generate_trace_id() local sampled if span.parent and span.parent.should_sample ~= nil then sampled = span.parent.should_sample elseif options.should_sample ~= nil then sampled = options.should_sample else if not tracer then sampled = false else local err sampled, err = tracer.sampler(trace_id) if err then sampled = false ngx_log(ngx_ERR, "sampler failure: ", err) end end end span.parent_id = span.parent and span.parent.span_id or options.parent_id span.tracer = span.tracer or tracer span.span_id = generate_span_id() span.trace_id = trace_id span.kind = options.span_kind or SPAN_KIND.INTERNAL -- get_sampling_decision() can be used to dynamically run the sampler's logic -- and obtain the sampling decision for the span. This way plugins can apply -- their configured sampling rate dynamically. The sampled flag can then be -- overwritten by set_should_sample. span.should_sample = sampled setmetatable(span, span_mt) return span end local function link_span(tracer, span, name, options) if tracer and type(tracer) ~= "table" then error("invalid tracer", 2) end validate_span_options(options) options = options or {} -- cache tracer ref, to get hooks / span processer -- tracer ref will not be cleared when the span table released span.tracer = span.tracer or tracer -- specify span start time span.start_time_ns = options.start_time_ns or ffi_time_unix_nano() span.attributes = options.attributes span.name = name span.linked = true -- insert the span to ctx local spans = tracer.get_spans() local len = spans[0] + 1 spans[len] = span spans[0] = len return span end local function new_span(tracer, name, options) if type(tracer) ~= "table" then error("invalid tracer", 2) end if type(name) ~= "string" or #name == 0 then error("invalid span name", 2) end local span = create_span(tracer, options) link_span(tracer, span, name, options) return span end --- Ends a Span -- Set the end time and release the span, -- the span table MUST not being used after ended. -- -- @function span:finish -- @tparam number|nil end_time_ns -- @usage -- span:finish() -- -- local time = ngx.now() -- span:finish(time * 100000000) function span_mt:finish(end_time_ns) if self.end_time_ns ~= nil then -- span is finished, and already processed return end if end_time_ns ~= nil and type(end_time_ns) ~= "number" then error("invalid span end time", 2) end if end_time_ns and end_time_ns < self.start_time_ns then ngx_log(ngx_ERR, "invalid span duration: ", end_time_ns - self.start_time_ns, " for span: ", self.name) return end self.end_time_ns = end_time_ns or ffi_time_unix_nano() if self.active and self.tracer.active_span() == self then self.tracer.set_active_span(self.parent) self.active = nil end end --- Set an attribute to a Span -- -- @function span:set_attribute -- @tparam string key -- @tparam string|number|boolean|nil value -- @usage -- span:set_attribute("net.transport", "ip_tcp") -- span:set_attribute("net.peer.port", 443) -- span:set_attribute("exception.escaped", true) -- span:set_attribute("unset.this", nil) 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 if value == nil then vtyp = value else vtyp = type(value) end -- TODO: any invalid type left? if vtyp ~= "string" and vtyp ~= "number" and vtyp ~= "boolean" and vtyp ~= "table" and vtyp ~= nil then -- 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 self.attributes = tablepool_fetch(POOL_ATTRIBUTES, 0, 4) end self.attributes[key] = value end --- Adds an event to a Span -- -- @function span:add_event -- @tparam string name Event name -- @tparam table|nil attributes Event attributes -- @tparam number|nil time_ns Event timestamp function span_mt:add_event(name, attributes, time_ns) if type(name) ~= "string" then error("invalid name", 2) end if attributes ~= nil and type(attributes) ~= "table" then error("invalid attribute", 2) end if self.events == nil then self.events = tablepool_fetch(POOL_EVENTS, 4, 0) self.events[0] = 0 end local obj = new_tab(0, 3) obj.name = name obj.time_ns = time_ns or ffi_time_unix_nano() if attributes then obj.attributes = attributes end local len = self.events[0] + 1 self.events[len] = obj self.events[0] = len end --- Adds an error event to a Span -- -- @function span:record_error -- @tparam string err error string function span_mt:record_error(err) if type(err) ~= "string" then err = tostring(err) end self:add_event("exception", { ["exception.message"] = err, }) end --- Adds an error event to a Span -- Status codes: -- - `0` unset -- - `1` ok -- - `2` error -- -- @function span:set_status -- @tparam number status status code function span_mt:set_status(status) if type(status) ~= "number" then error("invalid status", 2) end self.status = status end -- (internal) Release a span -- The lifecycle of span is controlled by Kong function span_mt:release() if type(self.attributes) == "table" then tablepool_release(POOL_ATTRIBUTES, self.attributes) end if type(self.events) == "table" then tablepool_release(POOL_EVENTS, self.events) end -- metabale will be cleared tablepool_release(POOL_SPAN, self) end -- (internal) compatible with Zipkin tracing headers -- TODO: implement baggage API function span_mt:each_baggage_item() return NOOP end local tracer_mt = {} tracer_mt.__index = tracer_mt -- avoid creating multiple tracer with same name local tracer_memo = setmetatable({}, { __mode = "k" }) local noop_tracer = {} noop_tracer.name = "noop" noop_tracer.start_span = function() return noop_span end noop_tracer.create_span = function() return noop_span end noop_tracer.get_spans = NOOP noop_tracer.get_root_span = NOOP noop_tracer.init_spans = NOOP noop_tracer.link_span = NOOP noop_tracer.active_span = NOOP noop_tracer.set_active_span = NOOP noop_tracer.process_span = NOOP noop_tracer.set_should_sample = NOOP noop_tracer.get_sampling_decision = NOOP noop_tracer.spans_table_key = "noop" local VALID_TRACING_PHASES = { ssl_cert = true, rewrite = true, access = true, header_filter = true, body_filter = true, log = true, content = true, } --- New Tracer local function new_tracer(name, options) name = name or "default" local namespace = options and options.namespace or "KONG" local cache_key = namespace .. "_" .. name if tracer_memo[cache_key] then return tracer_memo[cache_key] end local self = { -- instrumentation library name name = name, } options = options or {} if options.noop then return noop_tracer end options.sampling_rate = options.sampling_rate or 1.0 self.sampler = get_trace_id_based_sampler(options.sampling_rate) self.active_span_key = namespace .. "_" .. "active_span" self.spans_table_key = namespace .. "_" .. "SPANS" --- Get the active span -- Returns the root span by default -- -- @function kong.tracing.active_span -- @phases rewrite, access, header_filter, response, body_filter, log -- @treturn table span function self.active_span() if not VALID_TRACING_PHASES[ngx.get_phase()] then return end return ngx.ctx[self.active_span_key] end --- Set the active span -- -- @function kong.tracing.set_active_span -- @phases rewrite, access, header_filter, response, body_filter, log -- @tparam table span function self.set_active_span(span) if not VALID_TRACING_PHASES[ngx.get_phase()] then return end if span then span.active = true end ngx.ctx[self.active_span_key] = span end --- Create a new Span -- -- @function kong.tracing.start_span -- @phases rewrite, access, header_filter, response, body_filter, log -- @tparam string name span name -- @tparam table options -- @treturn table span function self.start_span(...) if not VALID_TRACING_PHASES[ngx.get_phase()] then return noop_span end return new_span(self, ...) end function self.create_span(...) return create_span(...) end function self.link_span(...) return link_span(...) end function self.init_spans() local spans = tablepool_fetch(POOL_SPAN_STORAGE, 10, 0) spans[0] = 0 -- span counter ngx.ctx[self.spans_table_key] = spans return spans end function self.get_spans() return ngx.ctx[self.spans_table_key] or self.init_spans() end function self.get_root_span() local spans = self.get_spans() if not spans then return end return spans[1] end --- Batch process spans -- Please note that socket is not available in the log phase, use `ngx.timer.at` instead -- -- @function kong.tracing.process_span -- @phases log -- @tparam function processor a function that accecpt a span as the parameter function self.process_span(processor, ...) check_phase(PHASES.log) if type(processor) ~= "function" then error("processor must be a function", 2) end local spans = self.get_spans() if not spans then return end for _, span in ipairs(spans) do if span.tracer and span.tracer.name == self.name then processor(span, ...) end end end --- Update the value of should_sample for all spans -- -- @function kong.tracing:set_should_sample -- @tparam bool should_sample value for the sample parameter function self:set_should_sample(should_sample) local spans = self.get_spans() if not spans then return end for _, span in ipairs(spans) do if span.is_recording ~= false then span.should_sample = should_sample end end end --- Get the sampling decision result -- -- Uses a parent-based sampler when the parent has sampled flag == false -- to inherit the non-recording decision from the parent span, or when -- trace_id is not available. -- -- Else, apply the probability-based should_sample decision. -- -- @function kong.tracing:get_sampling_decision -- @tparam bool parent_should_sample value of the parent span sampled flag -- extracted from the incoming tracing headers -- @tparam number sampling_rate the sampling rate to apply for the -- probability sampler -- @treturn bool sampled value of sampled for this trace function self:get_sampling_decision(parent_should_sample, plugin_sampling_rate) local ctx = ngx.ctx local sampled local root_span = self.get_root_span() local trace_id = tracing_context.get_raw_trace_id(ctx) local sampling_rate = plugin_sampling_rate or kong.configuration.tracing_sampling_rate if not root_span or root_span.attributes["kong.propagation_only"] then -- should not sample if there is no root span or if the root span is -- a dummy created only to propagate headers sampled = false elseif parent_should_sample == false or not trace_id then -- trace_id can be nil when tracing instrumentations are disabled -- and Kong is configured to only do headers propagation sampled = parent_should_sample elseif sampling_rate then -- use probability-based sampler local err sampled, err = self.sampler(trace_id, sampling_rate) if err then sampled = false ngx_log(ngx_ERR, "sampler failure: ", err) end end -- enforce boolean return not not sampled end tracer_memo[name] = setmetatable(self, tracer_mt) return tracer_memo[name] end tracer_mt.new = new_tracer noop_tracer.new = new_tracer local global_tracer tracer_mt.set_global_tracer = function(tracer) if type(tracer) ~= "table" or (getmetatable(tracer) ~= tracer_mt and tracer.name ~= "noop") then error("invalid tracer", 2) end global_tracer = tracer -- replace kong.pdk.tracer if kong then kong.tracing = tracer end end noop_tracer.set_global_tracer = tracer_mt.set_global_tracer global_tracer = new_tracer("core", { noop = true }) tracer_mt.__call = function(_, ...) return new_tracer(...) end setmetatable(noop_tracer, { __call = tracer_mt.__call, __newindex = NOOP, }) return { new = function() return global_tracer end, }