fix(active-tracing): safe access to instrumentation

This commit adds a safeguard to ensure instrumentation is inhibited
outside of a request context.

kong/enterprise_edition/debug_session/instrumentation/init.lua

@@ -22,6 +22,7 @@ local time_ns = require("kong.tools.time").time_ns
 
 local tablepool_release = tablepool.release
 local get_method = ngx.req.get_method
+local ngx_get_phase = ngx.get_phase
 local get_ctx_key = utils.get_ctx_key
 local log = utils.log
 local cjson_encode = cjson.encode
@@ -105,6 +106,22 @@ local SPAN_NAMES = {
   CLIENT_HEADERS = "kong.read_client_http_headers",
 }
 
+local VALID_TRACING_PHASES = {
+  ssl_cert = true,
+  rewrite = true,
+  access = true,
+  header_filter = true,
+  body_filter = true,
+  log = true,
+  content = true,
+}
+
+
+local function is_valid_phase()
+  local phase = ngx_get_phase()
+  return VALID_TRACING_PHASES[phase]
+end
+
 
 local function is_enabled(instrumentation)
   return band(enabled_instrums, instrumentation) ~= 0
@@ -138,6 +155,11 @@ end
 
 
 local function check_initialize_trace(start_time)
+  if not is_valid_phase() then
+    -- nothing to initialize
+    return
+  end
+
   start_time = start_time or time_ns()
   if not tracer.get_root_span() then
     create_root_span(start_time)
@@ -146,6 +168,11 @@ end
 
 
 local function start_subspan(...)
+  if not is_valid_phase() then
+    -- not in a request: ignore
+    return
+  end
+
   -- if a subspan is started while the session is starting, we skip it
   -- this avoids generating partial traces if a session is started mid-request
   if is_session_activating() then
@@ -950,6 +977,7 @@ _M.INSTRUMENTATIONS = INSTRUMENTATIONS
 
 _M.is_session_activating = is_session_activating
 _M.should_skip_instrumentation = should_skip_instrumentation
+_M.is_valid_phase = is_valid_phase
 
 -- add an instrumentation to a bitmask of enabled instrumentations
 -- @param number all_enabled the bitmask of all enabled instrumentations

kong/enterprise_edition/debug_session/instrumentation/redis.lua

@@ -39,6 +39,10 @@ function _M.instrument()
         return old_func(self, ...)
       end
 
+      if not instrum.is_valid_phase() then
+        return old_func(self, ...)
+      end
+
       if instrum.should_skip_instrumentation(instrum.INSTRUMENTATIONS.io) then
         return old_func(self, ...)
       end

kong/enterprise_edition/debug_session/instrumentation/socket.lua

@@ -37,6 +37,10 @@ local function patched_connect(self, ...)
     return old_tcp_connect(self, ...)
   end
 
+  if not instrum.is_valid_phase() then
+    return old_tcp_connect(self, ...)
+  end
+
   if instrum.should_skip_instrumentation(instrum.INSTRUMENTATIONS.io) then
     return old_tcp_connect(self, ...)
   end
@@ -61,6 +65,10 @@ local function patched_sslhandshake(self, ...)
     return old_tcp_sslhandshake(self, ...)
   end
 
+  if not instrum.is_valid_phase() then
+    return old_tcp_sslhandshake(self, ...)
+  end
+
   if instrum.should_skip_instrumentation(instrum.INSTRUMENTATIONS.io) then
     return old_tcp_sslhandshake(self, ...)
   end
@@ -84,6 +92,10 @@ local function patched_send(self, ...)
     return old_tcp_send(self, ...)
   end
 
+  if not instrum.is_valid_phase() then
+    return old_tcp_send(self, ...)
+  end
+
   if instrum.should_skip_instrumentation(instrum.INSTRUMENTATIONS.io) then
     return old_tcp_send(self, ...)
   end
@@ -107,6 +119,10 @@ local function patch_receive(self, ...)
     return old_tcp_receive(self, ...)
   end
 
+  if not instrum.is_valid_phase() then
+    return old_tcp_receive(self, ...)
+  end
+
   if instrum.should_skip_instrumentation(instrum.INSTRUMENTATIONS.io) then
     return old_tcp_receive(self, ...)
   end

spec-ee/01-unit/17-debuggability/06-instrumentation-io_spec.lua

@@ -0,0 +1,105 @@
+-- This software is copyright Kong Inc. and its licensors.
+-- Use of the software is subject to the agreement between your organization
+-- and Kong Inc. If there is no such agreement, use is governed by and
+-- subject to the terms of the Kong Master Software License Agreement found
+-- at https://konghq.com/enterprisesoftwarelicense/.
+-- [ END OF LICENSE 0867164ffc95e54f04670b5169c09574bdbd9bba ]
+
+
+local utils = require "kong.enterprise_edition.debug_session.utils"
+local helpers = require "spec.helpers"
+
+describe("Debug Session IO Instrumentation", function()
+  local instrum, tracer
+
+  lazy_setup(function()
+    package.loaded["kong.enterprise_edition.debug_session.instrumentation.init"] = nil
+    package.loaded["kong.enterprise_edition.debug_session.instrumentation.socket"] = nil
+    package.loaded["kong.enterprise_edition.debug_session.instrumentation.redis"] = nil
+
+    instrum = {}
+    tracer = {}
+
+    spy.on(tracer, "start_span")
+    spy.on(instrum, "is_valid_phase")
+    stub(instrum, "INSTRUMENTATIONS")
+    stub(instrum, "should_skip_instrumentation").returns(false)
+  end)
+
+  describe("Redis", function()
+    local redis, redis_instrum_mod
+    local REDIS_TOTAL_TIME_CTX_KEY = utils.get_ctx_key("redis_total_time")
+
+    lazy_setup(function()
+      redis = require "kong.enterprise_edition.tools.redis.v2"
+      redis_instrum_mod = require "kong.enterprise_edition.debug_session.instrumentation.redis"
+      redis_instrum_mod.instrument()
+      redis_instrum_mod.init({ tracer = tracer, instrum =  instrum })
+    end)
+
+    before_each(function()
+      tracer.start_span:clear()
+      instrum.should_skip_instrumentation:clear()
+      instrum.is_valid_phase:clear()
+    end)
+
+    it("get_total_time", function()
+      ngx.ctx[REDIS_TOTAL_TIME_CTX_KEY] = 1000000
+      assert.equals(1, redis_instrum_mod.get_total_time())
+    end)
+
+    it("does not execute patched code if outside of a request context", function()
+      local red = redis.connection({
+        host = helpers.redis_host,
+        port = helpers.redis_port,
+      })
+      red:set("foo", "bar")
+
+      assert.spy(instrum.is_valid_phase).was_called()
+      assert.stub(instrum.should_skip_instrumentation).was_not_called()
+      assert.spy(tracer.start_span).was_not_called()
+    end)
+  end)
+
+  describe("Socket", function()
+    local socket_instrum_mod, dynamic_hook
+    local SOCKET_TOTAL_TIME_CTX_KEY = utils.get_ctx_key("socket_total_time")
+
+    lazy_setup(function()
+      dynamic_hook = require "kong.dynamic_hook"
+      socket_instrum_mod = require "kong.enterprise_edition.debug_session.instrumentation.socket"
+      socket_instrum_mod.instrument()
+      socket_instrum_mod.init({ tracer = tracer, instrum = instrum })
+    end)
+
+    before_each(function()
+      tracer.start_span:clear()
+      instrum.should_skip_instrumentation:clear()
+      instrum.is_valid_phase:clear()
+
+      -- request scoped dynamic hooks don't work in timers
+      dynamic_hook.enable_by_default("active-tracing")
+    end)
+
+    lazy_teardown(function()
+      dynamic_hook.disable_by_default("active-tracing")
+    end)
+
+    it("get_total_time", function()
+      ngx.ctx[SOCKET_TOTAL_TIME_CTX_KEY] = 2000000
+      assert.equals(2, socket_instrum_mod.get_total_time())
+    end)
+
+    it("does not execute patched code if outside of a request context", function()
+      local sock = ngx.socket.tcp()
+      sock:connect("localhost", 4242)
+      sock:send("foo")
+      sock:receive("*a")
+      sock:close()
+
+      assert.spy(instrum.is_valid_phase).was_called(3)
+      assert.stub(instrum.should_skip_instrumentation).was_not_called()
+      assert.spy(tracer.start_span).was_not_called()
+    end)
+  end)
+end)