feat(*) restructure spans

Previously, each kong phase had a span. This changes them to logs (annotations in zipkin) with start and finish timestamps inside the proxy span and the request span. Each balancer try still is represented by a span, but these spans are now children of the request span instead of the proxy span. Their tags have been slightly modified too: `error` is now always present, and set to `true` or `false`. The span names for http traffic have been changed to: * `GET http://host:port` for the request span * `GET http://host:port (proxy)` for the proxy span * `GET http://host:port (balancer try n)` for each balancer try span
Kong · Nov 5, 2019 · c564b47 · c564b47
1 parent ad53010
commit c564b47
Show file tree

Hide file tree

Showing 3 changed files with 127 additions and 82 deletions.
diff --git a/README.md b/README.md
@@ -26,15 +26,20 @@ A tracer is created with the "http_headers" formatter set to use the headers des
 
 ## Spans
 
-  - `kong.request`: encompasing the whole request in kong.
-    All other spans are children of this.
-  - `kong.rewrite`: encompassing the kong rewrite phase
-  - `kong.proxy`: encompassing kong's time as a proxy
-    - `kong.access`: encompassing the kong access phase
-    - `kong.balancer`: each balancer phase will have it's own span
-    - `kong.header_filter`: encompassing the kong header filter phase
-    - `kong.body_filter`: encompassing the kong body filter phase
-
+  - *Request span*: 1 per request. Encompasses the whole request in kong (kind: `SERVER`).
+    The proxy span and balancer spans are children of this span.
+    Contains logs/annotations for the `kong.rewrite` phase start and end
+  - *Proxy span*: 1 per request. Encompassing most of Kong's internal processing of a request (kind: `CLIENT`)
+    Contains logs/annotations for the rest start/end of the rest of the kong phases:
+    `kong.access`, `kong.header_filter`, `kong.body_filter`, `kong.preread`
+  - *Balancer span(s)*: 0 or more per request, each encompassing one balancer attempt (kind: `CLIENT`)
+    Contains tags specific to the load balancing:
+    - `kong.balancer.try`: a number indicating the attempt order
+    - `peer.ipv4`/`peer.ipv6` + `peer.port` for the balanced port
+    - `error`: true/false depending on whether the balancing could be done or not
+    - `http.status_code`: the http status code received, in case of error
+    - `kong.balancer.state`: an nginx-specific description of the error: `next`/`failed` for HTTP failures, `0` for stream failures.
+      Equivalent to `state_name` in [OpenResty's Balancer's `get_last_failure` function](https://github.com/openresty/lua-resty-core/blob/master/lib/ngx/balancer.md#get_last_failure).
 
 ## Tags
 
@@ -47,6 +52,7 @@ Of those, this plugin currently uses:
   - `http.method`
   - `http.status_code`
   - `http.url`
+  - `error`
   - `peer.ipv4`
   - `peer.ipv6`
   - `peer.port`
@@ -66,5 +72,21 @@ In addition to the above standardised tags, this plugin also adds:
   - `kong.route`
   - `kong.service`
   - `kong.balancer.try`
-  - `kong.balancer.state`: see [here](https://github.com/openresty/lua-resty-core/blob/master/lib/ngx/balancer.md#get_last_failure) for possible values
-  - `kong.balancer.code`
+  - `kong.balancer.state`
+
+## Logs / Annotations
+
+Logs (annotations in Zipkin) are used to encode the begin and end of every kong phase.
+
+  - `kong.rewrite`, `start` / `finish`, `<timestamp>`
+  - `kong.access`, `start` / `finish`, `<timestamp>`
+  - `kong.preread`, `start` / `finish`, `<timestamp>`
+  - `kong.header_filter`, `start` / `finish`, `<timestamp>`
+  - `kong.body_filter`, `start` / `finish`, `<timestamp>`
+
+They are transmitted to Zipkin as annotations where the `value` is the concatenation of the log name and the value.
+
+For example, the `kong.rewrite`, `start` log would be transmitted as:
+
+  - `{ "value" = "kong.rewrite.start", timestamp = <timestamp> }`
+
diff --git a/kong/plugins/zipkin/opentracing.lua b/kong/plugins/zipkin/opentracing.lua
@@ -8,6 +8,7 @@ A plugin that derives this should:
 ]]
 
 local subsystem = ngx.config.subsystem
+local fmt = string.format
 
 local OpenTracingHandler = {
   VERSION = "scm",
@@ -53,6 +54,19 @@ local function ip_tag(addr)
 end
 
 
+-- adds the proxy span to the opentracing context, unless it already exists
+local function get_or_add_proxy_span(opentracing, timestamp)
+  if not opentracing.proxy_span then
+    local request_span = opentracing.request_span
+    opentracing.proxy_span = request_span:start_child_span(
+      request_span.name .. " (proxy)",
+      timestamp)
+    opentracing.proxy_span:set_tag("span.kind", "client")
+  end
+  return opentracing.proxy_span
+end
+
+
 if subsystem == "http" then
   function OpenTracingHandler:initialise_request(conf, ctx)
     local tracer = self:get_tracer(conf)
@@ -80,29 +94,26 @@ if subsystem == "http" then
       tracer = tracer,
       wire_context = wire_context,
       request_span = request_span,
-      rewrite_span = nil,
-      access_span = nil,
       proxy_span = nil,
-      header_filter_span = nil,
       header_filter_finished = false,
-      body_filter_span = nil,
     }
   end
 
 
-  function OpenTracingHandler:access(conf)
+  function OpenTracingHandler:rewrite(conf)
     local ctx = ngx.ctx
     local opentracing = self:get_context(conf, ctx)
+    -- note: rewrite is logged on the request_span, not on the proxy span
+    local rewrite_start = ctx.KONG_REWRITE_START / 1000
+    opentracing.request_span:log("kong.rewrite", "start", rewrite_start)
+  end
 
-    opentracing.proxy_span = opentracing.request_span:start_child_span(
-      "kong.proxy",
-      ctx.KONG_ACCESS_START / 1000
-    )
 
-    opentracing.access_span = opentracing.proxy_span:start_child_span(
-      "kong.access",
-      ctx.KONG_ACCESS_START / 1000
-    )
+  function OpenTracingHandler:access(conf)
+    local ctx = ngx.ctx
+    local opentracing = self:get_context(conf, ctx)
+
+    get_or_add_proxy_span(opentracing, ctx.KONG_ACCESS_START / 1000)
 
     -- Want to send headers to upstream
     local outgoing_headers = {}
@@ -117,20 +128,12 @@ if subsystem == "http" then
   function OpenTracingHandler:header_filter(conf)
     local ctx = ngx.ctx
     local opentracing = self:get_context(conf, ctx)
+    local header_filter_start =
+      ctx.KONG_HEADER_FILTER_STARTED_AT and ctx.KONG_HEADER_FILTER_STARTED_AT / 1000
+      or ngx.now()
 
-    local header_started = ctx.KONG_HEADER_FILTER_STARTED_AT and ctx.KONG_HEADER_FILTER_STARTED_AT / 1000 or ngx.now()
-
-    if not opentracing.proxy_span then
-      opentracing.proxy_span = opentracing.request_span:start_child_span(
-        "kong.proxy",
-        header_started
-      )
-    end
-
-    opentracing.header_filter_span = opentracing.proxy_span:start_child_span(
-      "kong.header_filter",
-      header_started
-    )
+    local proxy_span = get_or_add_proxy_span(opentracing, header_filter_start)
+    proxy_span:log("kong.header_filter", "start", header_filter_start)
   end
 
 
@@ -142,10 +145,9 @@ if subsystem == "http" then
     if not opentracing.header_filter_finished then
       local now = ngx.now()
 
-      opentracing.header_filter_span:finish(now)
+      opentracing.proxy_span:log("kong.header_filter", "finish", now)
       opentracing.header_filter_finished = true
-
-      opentracing.body_filter_span = opentracing.proxy_span:start_child_span("kong.body_filter", now)
+      opentracing.proxy_span:log("kong.body_filter", "start", now)
     end
   end
 
@@ -169,7 +171,6 @@ elseif subsystem == "stream" then
       tracer = tracer,
       wire_context = wire_context,
       request_span = request_span,
-      preread_span = nil,
       proxy_span = nil,
     }
   end
@@ -178,16 +179,10 @@ elseif subsystem == "stream" then
   function OpenTracingHandler:preread(conf)
     local ctx = ngx.ctx
     local opentracing = self:get_context(conf, ctx)
+    local preread_start = ctx.KONG_PREREAD_START / 1000
 
-    opentracing.proxy_span = opentracing.request_span:start_child_span(
-      "kong.proxy",
-      ctx.KONG_PREREAD_START / 1000
-    )
-
-    opentracing.preread_span = opentracing.proxy_span:start_child_span(
-      "kong.preread",
-      ctx.KONG_PREREAD_START / 1000
-    )
+    local proxy_span = get_or_add_proxy_span(opentracing, preread_start)
+    proxy_span:log("kong.preread", "start", preread_start)
   end
 end
 
@@ -197,42 +192,58 @@ function OpenTracingHandler:log(conf)
   local ctx = ngx.ctx
   local opentracing = self:get_context(conf, ctx)
   local request_span = opentracing.request_span
+  local proxy_span = get_or_add_proxy_span(opentracing, now)
 
-  local proxy_span = opentracing.proxy_span
-  if not proxy_span then
-    proxy_span = request_span:start_child_span("kong.proxy", now)
-    opentracing.proxy_span = proxy_span
-  end
-  proxy_span:set_tag("span.kind", "client")
-  local proxy_end = ctx.KONG_BODY_FILTER_ENDED_AT and ctx.KONG_BODY_FILTER_ENDED_AT/1000 or now
+  local proxy_finish =
+    ctx.KONG_BODY_FILTER_ENDED_AT and ctx.KONG_BODY_FILTER_ENDED_AT / 1000 or now
 
-  -- We'd run this in rewrite phase, but then we wouldn't have per-service configuration of this plugin
   if ctx.KONG_REWRITE_TIME then
-    opentracing.rewrite_span = opentracing.request_span:start_child_span(
-      "kong.rewrite",
-      ctx.KONG_REWRITE_START / 1000
-    ):finish((ctx.KONG_REWRITE_START + ctx.KONG_REWRITE_TIME) / 1000)
+    -- note: rewrite is logged on the request span, not on the proxy span
+    local rewrite_finish = (ctx.KONG_REWRITE_START + ctx.KONG_REWRITE_TIME) / 1000
+    opentracing.request_span:log("kong.rewrite", "finish", rewrite_finish)
   end
 
-  if opentracing.access_span then
-    opentracing.access_span:finish(ctx.KONG_ACCESS_ENDED_AT and ctx.KONG_ACCESS_ENDED_AT/1000 or proxy_end)
-  elseif opentracing.preread_span then
-    opentracing.preread_span:finish(ctx.KONG_PREREAD_ENDED_AT and ctx.KONG_PREREAD_ENDED_AT/1000 or proxy_end)
+  if subsystem == "http" then
+    -- add access_start here instead of in the access phase
+    -- because the plugin access phase is skipped when dealing with
+    -- requests which are not matched by any route
+    -- but we still want to know when the access phase "started"
+    local access_start = ctx.KONG_ACCESS_START / 1000
+    proxy_span:log("kong.access", "start", access_start)
+
+    local access_finish =
+      ctx.KONG_ACCESS_ENDED_AT and ctx.KONG_ACCESS_ENDED_AT / 1000 or proxy_finish
+    proxy_span:log("kong.access", "finish", access_finish)
+
+    if not opentracing.header_filter_finished then
+      proxy_span:log("kong.header_filter", "finish", now)
+      opentracing.header_filter_finished = true
+    end
+
+    proxy_span:log("kong.body_filter", "finish", now)
+
+  else
+    local preread_finish =
+      ctx.KONG_PREREAD_ENDED_AT and ctx.KONG_PREREAD_ENDED_AT / 1000 or proxy_finish
+    proxy_span:log("kong.preread", "finish", preread_finish)
   end
 
   local balancer_data = ctx.balancer_data
   if balancer_data then
     local balancer_tries = balancer_data.tries
-    for i=1, balancer_data.try_count do
+    for i = 1, balancer_data.try_count do
       local try = balancer_tries[i]
-      local span = proxy_span:start_child_span("kong.balancer", try.balancer_start / 1000)
+      local name = fmt("%s (balancer try %d)", request_span.name, i)
+      local span = request_span:start_child_span(name, try.balancer_start / 1000)
       span:set_tag(ip_tag(try.ip), try.ip)
       span:set_tag("peer.port", try.port)
       span:set_tag("kong.balancer.try", i)
       if i < balancer_data.try_count then
         span:set_tag("error", true)
         span:set_tag("kong.balancer.state", try.state)
-        span:set_tag("kong.balancer.code", try.code)
+        span:set_tag("http.status_code", try.code)
+      else
+        span:set_tag("error", false)
       end
       span:finish((try.balancer_start + try.balancer_latency) / 1000)
     end
@@ -243,15 +254,6 @@ function OpenTracingHandler:log(conf)
     proxy_span:set_tag("peer.port", balancer_data.port)
   end
 
-  if not opentracing.header_filter_finished and opentracing.header_filter_span then
-    opentracing.header_filter_span:finish(now)
-    opentracing.header_filter_finished = true
-  end
-
-  if opentracing.body_filter_span then
-    opentracing.body_filter_span:finish(proxy_end)
-  end
-
   if subsystem == "http" then
     request_span:set_tag("http.status_code", kong.response.get_status())
   end
@@ -262,18 +264,20 @@ function OpenTracingHandler:log(conf)
     request_span:set_tag("kong.credential", ctx.authenticated_credential.id)
   end
   request_span:set_tag("kong.node.id", kong.node.get_id())
+  -- TODO: should we add these tags to the request span and/or the balancer spans?
   if ctx.service and ctx.service.id then
     proxy_span:set_tag("kong.service", ctx.service.id)
     if ctx.route and ctx.route.id then
       proxy_span:set_tag("kong.route", ctx.route.id)
     end
-    if ctx.service.name ~= ngx.null then
+    if type(ctx.service.name) == "string" then
       proxy_span:set_tag("peer.service", ctx.service.name)
     end
   elseif ctx.api and ctx.api.id then
     proxy_span:set_tag("kong.api", ctx.api.id)
   end
-  proxy_span:finish(proxy_end)
+
+  proxy_span:finish(proxy_finish)
   request_span:finish(now)
 end
 

diff --git a/kong/plugins/zipkin/reporter.lua b/kong/plugins/zipkin/reporter.lua
@@ -3,6 +3,7 @@ local to_hex = require "resty.string".to_hex
 local cjson = require "cjson".new()
 cjson.encode_number_precision(16)
 
+local floor = math.floor
 
 local zipkin_reporter_methods = {}
 local zipkin_reporter_mt = {
@@ -92,20 +93,38 @@ function zipkin_reporter_methods:report(span)
     end
   end
 
+  local annotations do
+    local n_logs = span.n_logs
+    if n_logs > 0 then
+      annotations = kong.table.new(n_logs, 0)
+      for i = 1, n_logs do
+        local log = span.logs[i]
+        annotations[i] = {
+          event = log.key .. "." .. log.value,
+          timestamp = log.timestamp,
+        }
+      end
+    end
+  end
+
+  if not next(zipkin_tags) then
+    zipkin_tags = nil
+  end
+
   local zipkin_span = {
     traceId = to_hex(span_context.trace_id),
     name = span.name,
     parentId = span_context.parent_id and to_hex(span_context.parent_id) or nil,
     id = to_hex(span_context.span_id),
     kind = span_kind_map[span_kind],
     timestamp = span.timestamp * 1000000,
-    duration = math.floor(span.duration * 1000000), -- zipkin wants integer
+    duration = floor(span.duration * 1000000), -- zipkin wants integer
     -- shared = nil, -- We don't use shared spans (server reuses client generated spanId)
     -- TODO: debug?
     localEndpoint = localEndpoint,
     remoteEndpoint = remoteEndpoint,
     tags = zipkin_tags,
-    annotations = span.logs -- XXX: not guaranteed by documented opentracing-lua API to be in correct format
+    annotations = annotations,
   }
 
   local i = self.pending_spans_n + 1