feat(active_tracing): client ssl and headers spans (#11044)

* feat(active_tracing): tls handshake span

add a span that measures the tls handshake, to ensure there is no gap
between the end of the certificate span and the beginning of the
`read_client_http_headers` span.

* feat(active_tracing): read_client_http_headers span w/ http2

Before this commit there was a limitation where the span that measures
time spent reading client headers could only be created with http < 2.

* make the kong.read_client_http_headers span work with http2

kong/enterprise_edition/debug_session/instrumentation/init.lua

@@ -29,6 +29,7 @@ local get_ctx_key = utils.get_ctx_key
 local log = utils.log
 local cjson_encode = cjson.encode
 local new_tab = base.new_tab
+local concat = table.concat
 local split = ngx_re.split
 local band = bit.band
 local max = math.max
@@ -107,6 +108,7 @@ local SPAN_NAMES = {
   READ_BODY = "kong.read_client_http_body",
   CLIENT_HEADERS = "kong.read_client_http_headers",
   FLUSH_TO_DOWNSTREAM = "kong.wait_for_client_read",
+  TLS_HANDSHAKE = "kong.tls_handshake",
 }
 
 local VALID_TRACING_PHASES = {
@@ -703,17 +705,51 @@ local function initialize_trace(ctx)
 end
 
 
+-- this is an approximation of the tls handshake time, which occurs
+-- between the end of the certificate phase and the start of the request
+-- It includes the time the client waited, after connecting, before
+-- sending the request
+local function tls_handshake(ctx)
+  local start_time = ctx.connection and
+                     ctx.connection.KONG_CERTIFICATE_ENDED_AT_NS
+  if not start_time then
+    return
+  end
+
+  local span, err = subtracer.start_span(SPAN_NAMES.TLS_HANDSHAKE, {
+    span_kind = SPAN_KIND_SERVER,
+    start_time_ns = start_time,
+  })
+  if not span then
+    if err then
+      log(ngx_ERR, "failed to start span: ", err)
+    end
+    return
+  end
+
+  ngx.update_time()
+  local end_time = ngx.req.start_time() * 1e9
+  span:finish(end_time)
+end
+
+
 local function client_headers()
   ngx.update_time()
   local start_time = ngx.req.start_time() * 1e9
 
-  local ok, raw_header = pcall(ngx.req.raw_header, true)
-  if not ok then
-    log(ngx_DEBUG, "failed to get raw header: ", raw_header)
+  local headers_bytes = 0
+  local headers_num = 0
+  -- 1000 is the maximum num of headers we can get
+  local headers, err = kong.request.get_headers(1000)
+  if not headers then
+    log(ngx_ERR, "failed to get request headers: ", err)
     return
   end
-  local headers_bytes = raw_header and #raw_header or 0
-  local _, headers_num = raw_header:gsub("\n", "\n")
+  for k, v in pairs(headers) do
+    local val = type(v) == "table" and concat(v, "") or v
+    headers_bytes = headers_bytes + #k + #(val or "")
+    headers_num = headers_num + 1
+  end
 
   local span, err = subtracer.start_span(SPAN_NAMES.CLIENT_HEADERS, {
     span_kind = SPAN_KIND_SERVER,
@@ -760,6 +796,7 @@ function _M.rewrite(ctx)
   end
 
   initialize_trace(ctx)
+  tls_handshake(ctx)
   client_headers()
 
   return rewrite_phase()

kong/init.lua

@@ -1209,6 +1209,7 @@ function Kong.ssl_certificate()
   if debug_ssl_cert_phase_span then
     debug_ssl_cert_phase_span:finish()
   end
+  ctx.KONG_CERTIFICATE_ENDED_AT_NS = time_ns()
 
   ngx.ctx = {
     __index = {

spec-ee/02-integration/24-debuggability/03-instrumentation_spec.lua

@@ -44,11 +44,12 @@ local function SPAN_ATTRIBUTES(entities, opts)
 
   local path = opts and opts.path or "/sampled"
   local method = opts and opts.method or "GET"
+  local http_version = opts and opts.http_version or "1.1"
 
   return {
     ["kong"] = {
       ["proxy.kong.request.id"] = { assertion = "matches", expected_val = hex_128_pattern},
-      ["network.protocol.version"] = { assertion = "equals", expected_val = "1.1"},
+      ["network.protocol.version"] = { assertion = "equals", expected_val = http_version},
       ["proxy.kong.latency.upstream.read_response_duration"] = { assertion = "matches", expected_val = number_pattern},
       ["url.scheme"] = { assertion = "matches", expected_val = "http[s]?"},
       ["proxy.kong.latency.upstream"] = { assertion = "matches", expected_val = number_pattern},
@@ -132,6 +133,7 @@ local function SPAN_ATTRIBUTES(entities, opts)
       ["proxy.kong.sampling_rule"] = { assertion = "equals", expected_val = "http.route == \"/sampled\""},
     },
     ["kong.phase.certificate"] = {},
+    ["kong.tls_handshake"] = {},
     ["kong.phase.rewrite"] = {},
     ["kong.phase.access"] = {},
     ["kong.phase.header_filter"] = {},
@@ -241,6 +243,8 @@ local function assert_has_default_spans(spans, ssl, buffering, plugin_name)
   if ssl then
     local phase_certificate_span = assert_get_spans("kong.phase.certificate", spans, 1)
     assert_parent_child_relationship(root_span, phase_certificate_span)
+    local tls_handshake_span = assert_get_spans("kong.tls_handshake", spans, 1)
+    assert_parent_child_relationship(root_span, tls_handshake_span)
 
     if plugin_name then
       local plugin_certificate_span = assert_get_spans("kong.certificate.plugin." .. plugin_name, spans, 1)
@@ -380,6 +384,54 @@ describe("Active Tracing Instrumentation", function()
     end)
   end)
 
+  describe("#http2", function()
+    local http2_client, entities
+
+    lazy_setup(function()
+      entities = setup_kong()
+    end)
+
+    after_each(function()
+      teardown_analytics_sink(TCP_PORT)
+    end)
+
+    lazy_teardown(function()
+      teardown_kong()
+    end)
+
+    before_each(start_session)
+    after_each(stop_session)
+
+    it("produces the expected spans and attributes", function()
+      local trace = assert_produces_trace(function()
+        http2_client = helpers.http2_client("0.0.0.0", 9443, true)
+        local _, headers = http2_client {
+          headers = {
+            [":path"] = "/sampled",
+            [":method"] = "GET",
+            [":scheme"] = "https",
+            [":authority"] = "localhost",
+          },
+        }
+        return headers
+      end, TCP_PORT, "200", true)
+
+      assert_valid_trace(trace)
+
+      local spans = trace.resource_spans[1].scope_spans[1].spans
+      assert.True(spans and #spans > 0)
+      assert_has_default_spans(spans)
+
+      -- spans contain expected attributes
+      local opts = {
+        path = "/sampled",
+        method = "GET",
+        http_version = "2.0",
+      }
+      assert_spans_have_valid_attributes(spans, entities, opts)
+    end)
+  end)
+
   describe("#buffering enabled", function()
     local proxy_client, entities
     lazy_setup(function()

spec-ee/02-integration/24-debuggability/helpers.lua

@@ -45,7 +45,7 @@ local function setup_kong(cp_config, dp_config, db_setup)
 
   local route = bp.routes:insert({
     name = "sampled",
-    protocols = { "http" },
+    protocols = { "http", "https" },
     paths = { "/sampled" },
     service = { id = service.id },
   })
@@ -127,7 +127,7 @@ local function setup_kong(cp_config, dp_config, db_setup)
     request_debug = "off",
     cluster_rpc = "on",
     log_level = "debug",
-    proxy_listen = "0.0.0.0:9002, 0.0.0.0:9443 ssl",
+    proxy_listen = "0.0.0.0:9002, 0.0.0.0:9443 http2 ssl",
     nginx_conf = "spec/fixtures/custom_nginx.template",
     untrusted_lua = "on",
     konnect_mode = true,
@@ -184,10 +184,16 @@ local function teardown_analytics_sink(sink_port)
   pcall(helpers.kill_tcp_server, sink_port)
 end
 
-local function assert_produces_trace(request_func, sink_port, status)
+local function assert_produces_trace(request_func, sink_port, status, http2)
   local thread = helpers.tcp_server(sink_port)
   local res = request_func()
-  assert.response(res).has.status(status or 200)
+  local expected_status = status or 200
+
+  if http2 then
+    assert.equal(tostring(expected_status), res:get(":status"))
+  else
+    assert.response(res).has.status(expected_status)
+  end
 
   local ok, s_res = thread:join()
   pcall(helpers.kill_tcp_server, sink_port)