chore(logging): reduce excessive log flooding on debug logs

bin/busted

@@ -3,7 +3,6 @@
 setmetatable(_G, nil)
 
 local pl_path = require("pl.path")
-
 local pl_file = require("pl.file")
 
 local tools_system = require("kong.tools.system")
@@ -47,6 +46,7 @@ if not os.getenv("KONG_BUSTED_RESPAWNED") then
   end
   -- add cli recursion detection
   table.insert(script, "export KONG_BUSTED_RESPAWNED=1")
+  table.insert(script, "export KONG_IS_TESTING=1")
 
   -- rebuild the invoked commandline, while inserting extra resty-flags
   local resty_flags = DEFAULT_RESTY_FLAGS

bin/kong

@@ -142,9 +142,9 @@ require("kong.cmd.init")("%s", %s)
 
 local resty_ngx_log_level
 if arg.vv then
-  resty_ngx_log_level = "debug"
+  resty_ngx_log_level = skip_inject_cmds[cmd_name] and "notice" or "debug"
 elseif arg.v then
-  resty_ngx_log_level = "info"
+  resty_ngx_log_level = skip_inject_cmds[cmd_name] and "warn" or "info"
 end
 
 local resty_cmd = string.format(

kong/cache/init.lua

@@ -2,20 +2,21 @@ local resty_mlcache = require "kong.resty.mlcache"
 local buffer = require "string.buffer"
 
 
-local encode  = buffer.encode
-local type    = type
-local pairs   = pairs
-local error   = error
-local max     = math.max
-local ngx     = ngx
-local shared  = ngx.shared
+local encode = buffer.encode
+local type = type
+local pairs = pairs
+local error = error
+local max = math.max
+local ngx = ngx
+local shared = ngx.shared
 local ngx_log = ngx.log
+local get_phase = ngx.get_phase
 
 
 
-local ERR     = ngx.ERR
-local NOTICE  = ngx.NOTICE
-local DEBUG   = ngx.DEBUG
+local ERR = ngx.ERR
+local NOTICE = ngx.NOTICE
+local DEBUG = ngx.DEBUG
 
 
 local NO_TTL_FLAG = resty_mlcache.NO_TTL_FLAG
@@ -263,7 +264,9 @@ end
 
 
 function _M:purge()
-  log(NOTICE, "purging (local) cache")
+  if get_phase() ~= "timer" then
+    log(NOTICE, "purging (local) cache")
+  end
   local ok, err = self.mlcache:purge(true)
   if not ok then
     log(ERR, "failed to purge cache: ", err)

kong/cluster_events/init.lua

@@ -29,7 +29,7 @@ local poll_handler
 
 
 local function log(lvl, ...)
-  return ngx_log(lvl, "[cluster_events] ", ...)
+  return ngx_log(lvl, "[cluster events] ", ...)
 end
 
 
@@ -269,6 +269,8 @@ local function process_event(self, row, local_start_time)
 end
 
 
+local prev_min_at
+
 local function poll(self)
   -- get events since last poll
 
@@ -280,7 +282,10 @@ local function poll(self)
   if min_at then
     -- apply grace period
     min_at = min_at - self.poll_offset - 0.001
-    log(DEBUG, "polling events from: ", min_at)
+    if min_at ~= prev_min_at then
+      prev_min_at = min_at
+      log(DEBUG, "polling events from: ", min_at)
+    end
 
   else
     -- 'at' was evicted from 'kong' shm - safest is to resume fetching events

kong/clustering/control_plane.lua

@@ -127,7 +127,7 @@ function _M:export_deflated_reconfigure_payload()
   -- store serialized plugins map for troubleshooting purposes
   local shm_key_name = "clustering:cp_plugins_configured:worker_" .. (worker_id() or -1)
   kong_dict:set(shm_key_name, json_encode(self.plugins_configured))
-  ngx_log(ngx_DEBUG, "plugin configuration map key: ", shm_key_name, " configuration: ", kong_dict:get(shm_key_name))
+  kong.log.trace(_log_prefix, "plugin configuration map key: ", shm_key_name, " configuration: ", kong_dict:get(shm_key_name))
 
   local config_hash, hashes = calculate_config_hash(config_table)
 
@@ -374,7 +374,7 @@ function _M:handle_cp_websocket(cert)
         return nil, "invalid websocket frame received from data plane: " .. typ
       end
 
-      ngx_log(ngx_DEBUG, _log_prefix, "received ping frame from data plane", log_suffix)
+      kong.log.trace(_log_prefix, "received ping frame from data plane", log_suffix)
 
       config_hash = data
       last_seen = ngx_time()
@@ -420,7 +420,7 @@ function _M:handle_cp_websocket(cert)
           ngx_log(ngx_NOTICE, _log_prefix, "failed to send pong frame to data plane: ", err, log_suffix)
 
         else
-          ngx_log(ngx_DEBUG, _log_prefix, "sent pong frame to data plane", log_suffix)
+          kong.log.trace(_log_prefix, "sent pong frame to data plane", log_suffix)
         end
 
         -- pong ok

kong/clustering/data_plane.lua

@@ -394,10 +394,7 @@ function _M:communicate(premature)
       end
 
       if typ == "pong" then
-        ngx_log(ngx_DEBUG, _log_prefix,
-                "received pong frame from control plane",
-                log_suffix)
-
+        kong.log.trace(_log_prefix, "received pong frame from control plane", log_suffix)
         goto continue
       end
 

kong/clustering/rpc/manager.lua

@@ -387,7 +387,7 @@ function _M:_call_or_notify(is_notification, node_id, method, ...)
 
   local params = {...}
 
-  ngx_log(ngx_DEBUG,
+  kong.log.trace(
     _log_prefix,
     is_notification and "notifying " or "calling ",
     method,
@@ -403,7 +403,7 @@ function _M:_call_or_notify(is_notification, node_id, method, ...)
       return nil, err
     end
 
-    ngx_log(ngx_DEBUG, _log_prefix, method, " succeeded")
+    kong.log.trace(_log_prefix, method, " succeeded")
 
     return res
   end

kong/clustering/rpc/socket.lua

@@ -149,7 +149,7 @@ function _M:process_rpc_msg(payload, collection)
   if payload_method then
     -- invoke
 
-    ngx_log(ngx_DEBUG, "[rpc] got RPC call: ", payload_method, " (id: ", payload_id, ")")
+    kong.log.trace("[rpc] got RPC call: ", payload_method, " (id: ", payload_id, ")")
 
     local dispatch_cb = self.manager.callbacks.callbacks[payload_method]
     if not dispatch_cb and payload_id then

kong/clustering/services/sync/hooks.lua

@@ -99,7 +99,7 @@ function _M:register_dao_hooks()
   local function is_db_export(name)
     local db_export = kong.db[name].schema.db_export
 
-    ngx_log(ngx_DEBUG, "[kong.sync.v2] name: ", name, " db_export: ", db_export)
+    kong.log.trace("[kong.sync.v2] name: ", name, " db_export: ", db_export)
 
     return db_export == nil or db_export == true
   end

kong/clustering/services/sync/rpc.lua

@@ -71,7 +71,7 @@ function _M:init_cp(manager)
   -- Params: versions: list of current versions of the database
   -- example: { default = { version = "1000", }, }
   manager.callbacks:register("kong.sync.v2.get_delta", function(node_id, current_versions)
-    ngx_log(ngx_DEBUG, "[kong.sync.v2] config push (connected client)")
+    kong.log.trace("[kong.sync.v2] config push (connected client)")
 
     local rpc_peers
     if kong.rpc then

kong/db/strategies/postgres/connector.lua

@@ -34,7 +34,6 @@ local now_updated  = require("kong.tools.time").get_updated_now
 
 
 local WARN                          = ngx.WARN
-local DEBUG                         = ngx.DEBUG
 local SQL_INFORMATION_SCHEMA_TABLES = [[
 SELECT table_name
   FROM information_schema.tables
@@ -373,9 +372,9 @@ ORDER BY %s LIMIT 50000 FOR UPDATE SKIP LOCKED)
         end
 
         local _tracing_cleanup_end_time = now()
-        local time_elapsed = tonumber(fmt("%.3f", _tracing_cleanup_end_time - _tracing_cleanup_start_time))
-        log(DEBUG, "cleaning up expired rows from table '", table_names[i],
-                   "' took ", time_elapsed, " seconds")
+        local time_elapsed =  _tracing_cleanup_end_time - _tracing_cleanup_start_time
+        kong.log.trace(fmt("cleaning up expired rows from table '%s' took %.3f seconds",
+                       table_names[i], time_elapsed))
       end
     end)
   end

kong/dns/client.lua

@@ -8,7 +8,6 @@ local now = ngx.now
 local log = ngx.log
 local ERR = ngx.ERR
 local WARN = ngx.WARN
-local NOTICE = ngx.NOTICE
 local DEBUG = ngx.DEBUG
 local ALERT = ngx.ALERT
 local timer_at = ngx.timer.at
@@ -158,8 +157,8 @@ function _M.new(opts)
     end
   end
 
-  log(NOTICE, PREFIX, "supported types: ", enable_srv and "srv " or "",
-              enable_ipv4 and "ipv4 " or "", enable_ipv6 and "ipv6 " or "")
+  log(DEBUG, PREFIX, "supported types: ", enable_srv and "srv " or "",
+             enable_ipv4 and "ipv4 " or "", enable_ipv6 and "ipv6 " or "")
 
   -- parse resolv.conf
   local resolv, err = parse_resolv_conf(opts.resolv_conf, opts.enable_ipv6)
@@ -603,7 +602,7 @@ function _M:resolve_all(name, qtype, cache_only, tries, has_timing)
 
   local key = name .. ":" .. qtype
 
-  log(DEBUG, PREFIX, "resolve_all ", key)
+  --log(DEBUG, PREFIX, "resolve_all ", key)
 
   local stats = self.stats
 
@@ -629,8 +628,8 @@ function _M:resolve_all(name, qtype, cache_only, tries, has_timing)
     })
   end
 
-  log(DEBUG, PREFIX, "cache lookup ", key, " ans:", answers and #answers or "-",
-                     " hlv:", hit_str)
+  --log(DEBUG, PREFIX, "cache lookup ", key, " ans:", answers and #answers or "-",
+  --                   " hlv:", hit_str)
 
   if has_timing then
     req_dyn_hook_run_hook("timing", "dns:cache_lookup",

kong/llm/plugin/base.lua

@@ -48,7 +48,7 @@ local function run_stage(stage, sub_plugin, conf)
     elseif not ai_executed_filters[name] or REPEATED_PHASES[stage] then
       ai_executed_filters[name] = true
 
-      kong.log.debug("executing filter ", name)
+      kong.log.trace("executing filter ", name)
 
       local ok, err = f:run(conf)
       if not ok then

kong/pdk/log.lua

@@ -983,6 +983,10 @@ do
 end
 
 
+local IS_TESTING
+local NOOP = function() end
+
+
 local function new_log(namespace, format)
   if type(namespace) ~= "string" then
     error("namespace must be a string", 2)
@@ -1004,7 +1008,6 @@ local function new_log(namespace, format)
 
   local self = {}
 
-
   function self.set_format(fmt)
     if fmt and type(fmt) ~= "string" then
       error("format must be a string", 2)
@@ -1032,6 +1035,12 @@ local function new_log(namespace, format)
 
   self.inspect = new_inspect(namespace)
 
+  if IS_TESTING then
+    self.trace = self.debug
+  else
+    self.trace = NOOP
+  end
+
   self.set_serialize_value = set_serialize_value
   self.serialize = serialize
 
@@ -1045,6 +1054,9 @@ _log_mt.new = new_log
 
 return {
   new = function()
+    if IS_TESTING == nil then
+      IS_TESTING = os.getenv("KONG_IS_TESTING") == "1"
+    end
     return new_log("core", _DEFAULT_FORMAT)
   end,
 }

kong/tools/queue.lua

@@ -209,7 +209,7 @@ local function get_or_create_queue(queue_conf, handler, handler_conf)
 
   local queue = queues[key]
   if queue then
-    queue:log_debug("queue exists")
+    queue:log_trace("queue exists")
     -- We always use the latest configuration that we have seen for a queue and handler.
     queue.handler_conf = handler_conf
     return queue
@@ -243,17 +243,17 @@ local function get_or_create_queue(queue_conf, handler, handler_conf)
   if queue.concurrency_limit == 1 then
     kong.timer:named_at("queue " .. key, 0, function(_, q)
       while q:count() > 0 do
-        q:log_debug("processing queue")
+        q:log_trace("processing queue")
         q:process_once()
       end
-      q:log_debug("done processing queue")
+      q:log_trace("done processing queue")
       queues[key] = nil
     end, queue)
     queues[key] = queue
   end
 
 
-  queue:log_debug("queue created")
+  queue:log_trace("queue created")
 
   return queue
 end
@@ -274,6 +274,7 @@ function Queue:log(handler, formatstring, ...)
   end
 end
 
+function Queue:log_trace(...) self:log(kong.log.trace, ...) end
 function Queue:log_debug(...) self:log(kong.log.debug, ...) end
 function Queue:log_info(...) self:log(kong.log.info, ...) end
 function Queue:log_warn(...) self:log(kong.log.warn, ...) end
@@ -322,10 +323,10 @@ local function handle(self, entries)
   local start_time = now()
   local retry_count = 0
   while true do
-    self:log_debug("passing %d entries to handler", entry_count)
+    self:log_trace("passing %d entries to handler", entry_count)
     local status, ok, err = pcall(self.handler, self.handler_conf, entries)
     if status and ok == true then
-      self:log_debug("handler processed %d entries successfully", entry_count)
+      self:log_trace("handler processed %d entries successfully", entry_count)
       break
     end
 

spec/01-unit/27-queue_spec.lua

@@ -65,6 +65,7 @@ describe("plugin queue", function()
     end, {
       kong = {
         log = {
+          trace = function(message) return log('DEBUG', message) end,
           debug = function(message) return log('DEBUG', message) end,
           info = function(message) return log('INFO', message) end,
           warn = function(message) return log('WARN', message) end,

spec/02-integration/02-cmd/16-verbose_spec.lua

@@ -4,8 +4,7 @@ local meta = require "kong.meta"
 describe("kong cli verbose output", function()
   it("--vv outputs debug level log", function()
     local _, stderr, stdout = assert(helpers.kong_exec("version --vv"))
-    -- globalpatches debug log will be printed by upper level resty command that runs kong.cmd
-    assert.matches("installing the globalpatches", stderr)
+    assert.matches("gracefully shutting down", stderr)
     assert.matches("Kong: " .. meta._VERSION, stdout, nil, true)
   end)
 end)