From 676b2a7de05ddbc050252c1558eb6788aed3fa09 Mon Sep 17 00:00:00 2001 From: Aapo Talvensaari Date: Thu, 13 Feb 2025 20:12:17 +0200 Subject: [PATCH 1/2] chore(logging): reduce excessive log flooding on debug logs (#10652) Signed-off-by: Aapo Talvensaari --- bin/kong | 4 +-- kong/cache/init.lua | 25 +++++++++++-------- kong/cluster_events/init.lua | 9 +++++-- kong/clustering/control_plane.lua | 8 +++--- kong/clustering/data_plane.lua | 6 ++--- kong/clustering/rpc/manager.lua | 4 +-- kong/clustering/rpc/socket.lua | 2 +- kong/clustering/services/sync/hooks.lua | 2 +- kong/clustering/services/sync/rpc.lua | 2 +- kong/db/strategies/postgres/connector.lua | 7 +++--- kong/dns/client.lua | 11 ++++---- kong/llm/plugin/base.lua | 2 +- kong/pdk/log.lua | 14 ++++++++++- kong/tools/queue.lua | 13 +++++----- spec/01-unit/27-queue_spec.lua | 1 + .../02-integration/02-cmd/16-verbose_spec.lua | 3 +-- 16 files changed, 66 insertions(+), 47 deletions(-) diff --git a/bin/kong b/bin/kong index e03b945314c..5c2d0be7478 100755 --- a/bin/kong +++ b/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( diff --git a/kong/cache/init.lua b/kong/cache/init.lua index 91b21c64a1a..5cffb0b93cf 100644 --- a/kong/cache/init.lua +++ b/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) diff --git a/kong/cluster_events/init.lua b/kong/cluster_events/init.lua index a8cfe5d700c..3ed347f66b3 100644 --- a/kong/cluster_events/init.lua +++ b/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 diff --git a/kong/clustering/control_plane.lua b/kong/clustering/control_plane.lua index 057e117d259..ecc41c63efd 100644 --- a/kong/clustering/control_plane.lua +++ b/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("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) + --ngx_log(ngx_DEBUG, _log_prefix, "received ping frame from data plane", log_suffix) config_hash = data last_seen = ngx_time() @@ -419,8 +419,8 @@ 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) + --else + -- ngx_log(ngx_DEBUG, _log_prefix, "sent pong frame to data plane", log_suffix) end -- pong ok diff --git a/kong/clustering/data_plane.lua b/kong/clustering/data_plane.lua index 91dea9ab1f4..2a44ef9cd44 100644 --- a/kong/clustering/data_plane.lua +++ b/kong/clustering/data_plane.lua @@ -394,9 +394,9 @@ 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(ngx_DEBUG, _log_prefix, + "received pong frame from control plane", + log_suffix) goto continue end diff --git a/kong/clustering/rpc/manager.lua b/kong/clustering/rpc/manager.lua index bd33f9db0a6..ea2b88fbcea 100644 --- a/kong/clustering/rpc/manager.lua +++ b/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 diff --git a/kong/clustering/rpc/socket.lua b/kong/clustering/rpc/socket.lua index f4d23cd6ebe..540f74bf33b 100644 --- a/kong/clustering/rpc/socket.lua +++ b/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 diff --git a/kong/clustering/services/sync/hooks.lua b/kong/clustering/services/sync/hooks.lua index 7712438d43e..96612d4927c 100644 --- a/kong/clustering/services/sync/hooks.lua +++ b/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 diff --git a/kong/clustering/services/sync/rpc.lua b/kong/clustering/services/sync/rpc.lua index 3dbacf68f2b..4105470dc34 100644 --- a/kong/clustering/services/sync/rpc.lua +++ b/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 diff --git a/kong/db/strategies/postgres/connector.lua b/kong/db/strategies/postgres/connector.lua index 0c5964f9230..f8fcb5a1b08 100644 --- a/kong/db/strategies/postgres/connector.lua +++ b/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 diff --git a/kong/dns/client.lua b/kong/dns/client.lua index 21e7b367bc6..b9e131f7891 100644 --- a/kong/dns/client.lua +++ b/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", diff --git a/kong/llm/plugin/base.lua b/kong/llm/plugin/base.lua index 531c45583db..5ba9319c87a 100644 --- a/kong/llm/plugin/base.lua +++ b/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 diff --git a/kong/pdk/log.lua b/kong/pdk/log.lua index e908e98ac1d..9c452888377 100644 --- a/kong/pdk/log.lua +++ b/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, } diff --git a/kong/tools/queue.lua b/kong/tools/queue.lua index 37284862b48..8ba08a7910e 100644 --- a/kong/tools/queue.lua +++ b/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 diff --git a/spec/01-unit/27-queue_spec.lua b/spec/01-unit/27-queue_spec.lua index 5d9eeeea7e7..e91c6891e51 100644 --- a/spec/01-unit/27-queue_spec.lua +++ b/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, diff --git a/spec/02-integration/02-cmd/16-verbose_spec.lua b/spec/02-integration/02-cmd/16-verbose_spec.lua index 6257e7b85b6..3fc3fc54718 100644 --- a/spec/02-integration/02-cmd/16-verbose_spec.lua +++ b/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) From d8c8e4938176c4629875ce2a2d5d1567a3c2245d Mon Sep 17 00:00:00 2001 From: Aapo Talvensaari Date: Thu, 13 Feb 2025 18:21:23 +0000 Subject: [PATCH 2/2] chore(logging): reduce excessive log flooding on debug logs (follow up) I merged the PR https://github.com/Kong/kong-ee/pull/10652 prematurely. This adds a couple of log messages back for testing. Signed-off-by: Aapo Talvensaari --- bin/busted | 2 +- kong/clustering/control_plane.lua | 8 ++++---- kong/clustering/data_plane.lua | 5 +---- 3 files changed, 6 insertions(+), 9 deletions(-) diff --git a/bin/busted b/bin/busted index 5be3493b056..e5e64e59f14 100755 --- a/bin/busted +++ b/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 diff --git a/kong/clustering/control_plane.lua b/kong/clustering/control_plane.lua index ecc41c63efd..035f54d1ffb 100644 --- a/kong/clustering/control_plane.lua +++ b/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)) - kong.log.trace("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() @@ -419,8 +419,8 @@ 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) + else + kong.log.trace(_log_prefix, "sent pong frame to data plane", log_suffix) end -- pong ok diff --git a/kong/clustering/data_plane.lua b/kong/clustering/data_plane.lua index 2a44ef9cd44..8dfdfbc1907 100644 --- a/kong/clustering/data_plane.lua +++ b/kong/clustering/data_plane.lua @@ -394,10 +394,7 @@ function _M:communicate(premature) end if typ == "pong" then - kong.log.trace(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