tests(request-debug): improve integration tests (#11692)

* tests(request-debug): only initialize DB once in test setup

This updates the test setup logic such that helpers.get_db_utils() is
only invoked once per test DB strategy.

BEFORE:
======= 30 tests from 1 test file ran. (64157.77 ms total)

AFTER:
======= 30 tests from 1 test file ran. (52507.36 ms total)

* tests(request-debug): truncate error.log before request

This updates the tests to truncate the error.log file before making a
request that will generate a log entry. The goal is to reduce the
overall amount of bytes that must be read from disk and searched
through.

* tests(request-debug): use line-wise parser for log entries

This updates the request debug log entry logic to use `io.lines()`
rather than reading the whole file at once. This improves performance
and memory usage in the worst-case scenarios of the function.

* tests(request-debug): ensure client connection is closed

spec/02-integration/21-request-debug/01-request-debug_spec.lua

@@ -3,6 +3,8 @@ local cjson               = require "cjson"
 local pl_path             = require "pl.path"
 local pl_file             = require "pl.file"
 local http_mock           = require "spec.helpers.http_mock"
+local string_buffer       = require "string.buffer"
+local clear_tab           = require "table.clear"
 
 local CP_PREFIX           = "servroot_cp"
 local DP_PREFIX           = "servroot_dp"
@@ -11,6 +13,7 @@ local TOKEN_FILE          = ".request_debug_token"
 local PLGUINS_ENABLED     = "bundled,enable-buffering-response,muti-external-http-calls"
 local TIME_TO_FIRST_BYTE  = 250  -- milliseconds
 local STREAMING           = 400  -- seconds
+local DB_INIT             = {}
 
 
 
@@ -143,19 +146,31 @@ local function get_output_header(_deployment, path, filter, fake_ip, token)
   })
   assert.not_same(500, res.status)
   res:read_body() -- discard body
+  proxy_client:close()
 
   if not res.headers["X-Kong-Request-Debug-Output"] then
     return nil
   end
 
   local json = assert(cjson.decode(res.headers["X-Kong-Request-Debug-Output"]))
   assert.falsy(json.dangling)
-  proxy_client:close()
   return json
 end
 
 
 local function get_output_log(deployment, path, filter, fake_ip, token)
+  local errlog
+
+  if deployment == "traditional" then
+    errlog = pl_path.join(helpers.test_conf.prefix, "logs/error.log")
+
+  else
+    assert(deployment == "hybrid", "unknown deploy mode")
+    errlog = pl_path.join(DP_PREFIX, "logs/error.log")
+  end
+
+  helpers.clean_logfile(errlog)
+
   local proxy_client = helpers.proxy_client()
   local res = assert(proxy_client:send {
     method = "GET",
@@ -169,6 +184,7 @@ local function get_output_log(deployment, path, filter, fake_ip, token)
   })
   assert.not_same(500, res.status)
   res:read_body() -- discard body
+  proxy_client:close()
 
   if not res.headers["X-Kong-Request-Debug-Output"] then
     return nil
@@ -177,49 +193,69 @@ local function get_output_log(deployment, path, filter, fake_ip, token)
   local output = assert(cjson.decode(res.headers["X-Kong-Request-Debug-Output"]))
   local debug_id = assert(output.debug_id)
 
+  local json
+  local truncated = false
+
+  local buf = string_buffer.new()
+
   local keyword = "[request-debug] id: " .. debug_id
+  local single_pattern = [[ output: (?<data>.+) while logging request, client]]
+  local multi_pattern = [[ parts: (?<part>\d+)/(?<parts>\d+) output: (?<data>.+) while logging request, client]]
 
-  if deployment == "traditional" then
-    path = pl_path.join(helpers.test_conf.prefix, "logs/error.log")
+  local deadline = ngx.now() + 5
 
-  else
-    assert(deployment == "hybrid", "unknown deploy mode")
-    path = pl_path.join(DP_PREFIX, "logs/error.log")
-  end
+  while ngx.now() < deadline do
+    buf:reset()
 
-  local json
-  local truncated = false
+    local fh = assert(io.open(errlog, "r"))
+    local captures = {}
+
+    for line in fh:lines() do
+      if line:find(keyword, nil, true) then
+        clear_tab(captures)
+
+        if ngx.re.match(line, multi_pattern, "oj", nil, captures) then
+          truncated = true
+
+          local part_num = assert(tonumber(captures.part))
+          local parts_total = assert(tonumber(captures.parts))
+
+          assert(part_num <= parts_total)
 
-  pcall(function()
-    helpers.pwait_until(function()
-      json = ""
-      local content = assert(pl_file.read(path))
-      local start_idx = assert(content:find(keyword, nil, true))
-      start_idx = assert(content:find("output: ", start_idx, true))
-      local end_idx
-
-      while true do
-        end_idx = assert(content:find(" while logging request", start_idx, true))
-        json = json .. content:sub(start_idx + #"output: ", end_idx - 1)
-        start_idx = content:find(keyword, end_idx, true)
-        if not start_idx then
+          local data = assert(captures.data)
+          buf:put(data)
+
+          if part_num == parts_total then
+            json = cjson.decode(buf:get())
+            break
+          end
+
+        elseif ngx.re.match(line, single_pattern, "oj", nil, captures) then
+          local data = assert(captures.data)
+          json = cjson.decode(data)
           break
-        end
 
-        truncated = true
-        start_idx = assert(content:find("output: ", start_idx, true))
+        else
+          error("unexpected error.log line: " .. line)
+        end
       end
+    end
 
-      json = assert(cjson.decode(json))
-    end, 10)
-  end)
+    fh:close()
+
+    if json ~= nil then
+      break
+    end
+
+    ngx.sleep(0.05)
+  end
 
   if not json then
     return nil
   end
 
   assert.falsy(json.dangling)
-  proxy_client:close()
+  assert.same(debug_id, json.debug_id)
 
   return json, truncated
 end
@@ -262,10 +298,13 @@ local function start_kong(strategy, deployment, disable_req_dbg, token)
     request_debug = "off"
   end
 
-  helpers.get_db_utils(strategy, nil, {
-    "enable-buffering-response",
-    "muti-external-http-calls",
-  })
+  if not DB_INIT[strategy] then
+    helpers.get_db_utils(strategy, nil, {
+      "enable-buffering-response",
+      "muti-external-http-calls",
+    })
+    DB_INIT[strategy] = true
+  end
 
   if deployment == "traditional" then
     assert(helpers.start_kong({
@@ -396,7 +435,7 @@ describe(desc, function()
           ngx.sleep(%s / 1000)
           ngx.print("Hello")
           ngx.flush(true)
-  
+
           ngx.sleep(%s / 1000)
           ngx.print(" World!")
           ngx.flush(true)