From 7e9e88f554637b9297bab25b853302990b54a364 Mon Sep 17 00:00:00 2001 From: Kurt Tu <131840510+sabertobihwy@users.noreply.github.com> Date: Wed, 20 Sep 2023 22:59:21 +0800 Subject: [PATCH] fix(pdk): use deep copies of Route, Service, and Consumer objects when log serialize (#11566) In the function of `kong.log.serialize`, the lifecycle of three table `ctx.route`, `ctx.service` and `ctx.authenticated_consumer` is across request. Modifying the sub-items in the current request of the table will affect the next request, resulting in unexpected behavior in Kong. Fix FTI-5357 --------- Signed-off-by: sabertobihwy --- CHANGELOG/unreleased/kong/11566.yaml | 7 + kong/pdk/log.lua | 16 +- spec/01-unit/10-log_serializer_spec.lua | 34 ++- spec/02-integration/07-sdk/02-log_spec.lua | 339 +++++++++++++++++++++ 4 files changed, 385 insertions(+), 11 deletions(-) create mode 100644 CHANGELOG/unreleased/kong/11566.yaml diff --git a/CHANGELOG/unreleased/kong/11566.yaml b/CHANGELOG/unreleased/kong/11566.yaml new file mode 100644 index 000000000000..317a9c3ac93f --- /dev/null +++ b/CHANGELOG/unreleased/kong/11566.yaml @@ -0,0 +1,7 @@ +message: "use deep copies of Route, Service, and Consumer objects when log serializing" +type: bugfix +scope: PDK +prs: + - 11566 +jiras: + - "FTI-5357" diff --git a/kong/pdk/log.lua b/kong/pdk/log.lua index cf24b5b7f1f5..bfea8544ab6b 100644 --- a/kong/pdk/log.lua +++ b/kong/pdk/log.lua @@ -16,7 +16,7 @@ local inspect = require "inspect" local ngx_ssl = require "ngx.ssl" local phase_checker = require "kong.pdk.private.phases" local utils = require "kong.tools.utils" - +local cycle_aware_deep_copy = utils.cycle_aware_deep_copy local sub = string.sub local type = type @@ -802,7 +802,7 @@ do end end - -- The value of upstream_status is a string, and status codes may be + -- The value of upstream_status is a string, and status codes may be -- seperated by comma or grouped by colon, according to -- the nginx doc: http://nginx.org/en/docs/http/ngx_http_upstream_module.html#upstream_status local upstream_status = var.upstream_status or "" @@ -832,9 +832,9 @@ do }, tries = (ctx.balancer_data or {}).tries, authenticated_entity = build_authenticated_entity(ctx), - route = ctx.route, - service = ctx.service, - consumer = ctx.authenticated_consumer, + route = cycle_aware_deep_copy(ctx.route), + service = cycle_aware_deep_copy(ctx.service), + consumer = cycle_aware_deep_copy(ctx.authenticated_consumer), client_ip = var.remote_addr, started_at = okong.request.get_start_time(), } @@ -873,9 +873,9 @@ do }, tries = (ctx.balancer_data or {}).tries, authenticated_entity = build_authenticated_entity(ctx), - route = ctx.route, - service = ctx.service, - consumer = ctx.authenticated_consumer, + route = cycle_aware_deep_copy(ctx.route), + service = cycle_aware_deep_copy(ctx.service), + consumer = cycle_aware_deep_copy(ctx.authenticated_consumer), client_ip = var.remote_addr, started_at = okong.request.get_start_time(), } diff --git a/spec/01-unit/10-log_serializer_spec.lua b/spec/01-unit/10-log_serializer_spec.lua index a23341b63acc..e6be436df72b 100644 --- a/spec/01-unit/10-log_serializer_spec.lua +++ b/spec/01-unit/10-log_serializer_spec.lua @@ -31,7 +31,7 @@ describe("kong.log.serialize", function() bytes_sent = "99", request_time = "2", remote_addr = "1.1.1.1", - -- may be a non-numeric string, + -- may be a non-numeric string, -- see http://nginx.org/en/docs/http/ngx_http_upstream_module.html#var_upstream_addr upstream_status = "500, 200 : 200, 200", }, @@ -116,7 +116,7 @@ describe("kong.log.serialize", function() end) it("serializes the Consumer object", function() - ngx.ctx.authenticated_consumer = {id = "someconsumer"} + ngx.ctx.authenticated_consumer = { id = "someconsumer" } local res = kong.log.serialize({ngx = ngx, kong = kong, }) assert.is_table(res) @@ -186,6 +186,20 @@ describe("kong.log.serialize", function() assert.equal("/upstream_uri" .. "?" .. args, res.upstream_uri) end) + + it("use the deep copies of the Route, Service, Consumer object avoid " .. + "modify ctx.authenticated_consumer, ctx.route, ctx.service", function() + ngx.ctx.authenticated_consumer = { id = "someconsumer" } + ngx.ctx.route = { id = "my_route" } + ngx.ctx.service = { id = "my_service" } + local res = kong.log.serialize({ngx = ngx, kong = kong, }) + assert.not_equal(tostring(ngx.ctx.authenticated_consumer), + tostring(res.consumer)) + assert.not_equal(tostring(ngx.ctx.route), + tostring(res.route)) + assert.not_equal(tostring(ngx.ctx.service), + tostring(res.service)) + end) end) end) @@ -283,7 +297,7 @@ describe("kong.log.serialize", function() end) it("serializes the Consumer object", function() - ngx.ctx.authenticated_consumer = {id = "someconsumer"} + ngx.ctx.authenticated_consumer = { id = "someconsumer" } local res = kong.log.serialize({ngx = ngx, kong = kong, }) assert.is_table(res) @@ -341,6 +355,20 @@ describe("kong.log.serialize", function() assert.is_nil(res.tries) end) + + it("use the deep copies of the Route, Service, Consumer object avoid " .. + "modify ctx.authenticated_consumer, ctx.route, ctx.service", function() + ngx.ctx.authenticated_consumer = { id = "someconsumer "} + ngx.ctx.route = { id = "my_route" } + ngx.ctx.service = { id = "my_service" } + local res = kong.log.serialize({ngx = ngx, kong = kong, }) + assert.not_equal(tostring(ngx.ctx.authenticated_consumer), + tostring(res.consumer)) + assert.not_equal(tostring(ngx.ctx.route), + tostring(res.route)) + assert.not_equal(tostring(ngx.ctx.service), + tostring(res.service)) + end) end) end) end) diff --git a/spec/02-integration/07-sdk/02-log_spec.lua b/spec/02-integration/07-sdk/02-log_spec.lua index fff9061a4c23..7f2b7e607b4a 100644 --- a/spec/02-integration/07-sdk/02-log_spec.lua +++ b/spec/02-integration/07-sdk/02-log_spec.lua @@ -1,4 +1,6 @@ local helpers = require "spec.helpers" +local cjson = require "cjson" +local FILE_LOG_PATH = os.tmpname() local function find_in_file(f, pat) @@ -121,3 +123,340 @@ describe("PDK: kong.log", function() f:close() end) end) + +for _, strategy in helpers.each_strategy() do + describe("PDK: make sure kong.log.serialize() will not modify ctx which's lifecycle " .. + "is across request [#" .. strategy .. "]", function() + describe("ctx.authenticated_consumer", function() + local proxy_client + local bp + + lazy_setup(function() + bp, _ = helpers.get_db_utils(strategy, { + "routes", + "services", + "plugins", + "consumers", + "acls", + "keyauth_credentials", + }) + + local consumer = bp.consumers:insert( { + username = "foo", + }) + + bp.keyauth_credentials:insert { + key = "test", + consumer = { id = consumer.id }, + } + + bp.acls:insert { + group = "allowed", + consumer = consumer, + } + + local route1 = bp.routes:insert { + paths = { "/status/200" }, + } + + bp.plugins:insert { + name = "acl", + route = { id = route1.id }, + config = { + allow = { "allowed" }, + }, + } + + bp.plugins:insert { + name = "key-auth", + route = { id = route1.id }, + } + + bp.plugins:insert { + name = "file-log", + route = { id = route1.id }, + config = { + path = FILE_LOG_PATH, + reopen = false, + custom_fields_by_lua = { + ["consumer.id"] = "return nil", + }, + }, + protocols = { + "http" + }, + } + + assert(helpers.start_kong({ + plugins = "bundled", + database = strategy, + nginx_conf = "spec/fixtures/custom_nginx.template", + db_cache_warmup_entities = "keyauth_credentials,consumers,acls", + nginx_worker_processes = 1, + })) + end) + + before_each(function() + proxy_client = helpers.proxy_client() + end) + + after_each(function () + proxy_client:close() + end) + + lazy_teardown(function() + helpers.stop_kong() + end) + + it("use the deep copy of Consumer object", function() + for i = 1, 3 do + local res = proxy_client:send { + method = "GET", + path = "/status/200", + headers = { + ["apikey"] = "test", + } + } + assert.res_status(200, res) + end + end) + end) + + describe("ctx.service", function() + local proxy_client + local bp + + lazy_setup(function() + bp, _ = helpers.get_db_utils(strategy, { + "routes", + "services", + "plugins", + },{ + "error-handler-log", + }) + + local service = bp.services:insert { + name = "example", + host = helpers.mock_upstream_host, + port = helpers.mock_upstream_port, + } + + local route1 = bp.routes:insert { + paths = { "/status/200" }, + service = service, + } + + bp.plugins:insert { + name = "error-handler-log", + config = {}, + } + + bp.plugins:insert { + name = "file-log", + route = { id = route1.id }, + config = { + path = FILE_LOG_PATH, + reopen = false, + custom_fields_by_lua = { + ["service.name"] = "return nil", + }, + }, + protocols = { + "http" + }, + } + + assert(helpers.start_kong({ + plugins = "bundled, error-handler-log", + database = strategy, + nginx_conf = "spec/fixtures/custom_nginx.template", + nginx_worker_processes = 1, + })) + end) + + before_each(function() + proxy_client = helpers.proxy_client() + end) + + after_each(function () + proxy_client:close() + end) + + lazy_teardown(function() + helpers.stop_kong() + end) + + it("use the deep copy of Service object", function() + for i = 1, 3 do + local res = proxy_client:send { + method = "GET", + path = "/status/200", + } + assert.res_status(200, res) + + local service_matched_header = res.headers["Log-Plugin-Service-Matched"] + assert.equal(service_matched_header, "example") + end + end) + end) + + describe("ctx.route", function() + local proxy_client + local bp + + lazy_setup(function() + bp, _ = helpers.get_db_utils(strategy, { + "routes", + "services", + "plugins", + }) + + local service = bp.services:insert { + host = helpers.mock_upstream_host, + port = helpers.mock_upstream_port, + } + + local route1 = bp.routes:insert { + name = "route1", + paths = { "/status/200" }, + service = service, + } + + assert(bp.plugins:insert { + name = "request-termination", + route = { id = route1.id }, + config = { + status_code = 418, + message = "No coffee for you. I'm a teapot.", + echo = true, + }, + }) + + bp.plugins:insert { + name = "file-log", + route = { id = route1.id }, + config = { + path = FILE_LOG_PATH, + reopen = false, + custom_fields_by_lua = { + ["route.name"] = "return nil", + }, + }, + protocols = { + "http" + }, + } + + assert(helpers.start_kong({ + plugins = "bundled, error-handler-log", + database = strategy, + nginx_conf = "spec/fixtures/custom_nginx.template", + nginx_worker_processes = 1, + })) + end) + + before_each(function() + proxy_client = helpers.proxy_client() + end) + + after_each(function () + proxy_client:close() + end) + + lazy_teardown(function() + helpers.stop_kong() + end) + + it("use the deep copy of Route object", function() + for i = 1, 3 do + local res = proxy_client:send { + method = "GET", + path = "/status/200", + } + + local body = assert.res_status(418, res) + local json = cjson.decode(body) + assert.equal(json["matched_route"]["name"], "route1") + end + end) + end) + + describe("in stream subsystem# ctx.authenticated_consumer", function() + local proxy_client + local bp + + local MESSAGE = "echo, ping, pong. echo, ping, pong. echo, ping, pong.\n" + lazy_setup(function() + bp, _ = helpers.get_db_utils(strategy, { + "routes", + "services", + "plugins", + }) + + local service = assert(bp.services:insert { + host = helpers.mock_upstream_host, + port = helpers.mock_upstream_stream_port, + protocol = "tcp", + }) + + local route1 = bp.routes:insert({ + destinations = { + { port = 19000 }, + }, + protocols = { + "tcp", + }, + service = service, + }) + + bp.plugins:insert { + name = "file-log", + route = { id = route1.id }, + config = { + path = FILE_LOG_PATH, + reopen = false, + custom_fields_by_lua = { + ["service.port"] = "return nil", + ["service.host"] = "return nil", + }, + }, + protocols = { + "tcp" + }, + } + + assert(helpers.start_kong({ + plugins = "bundled, error-handler-log", + database = strategy, + nginx_conf = "spec/fixtures/custom_nginx.template", + nginx_worker_processes = 1, + stream_listen = helpers.get_proxy_ip(false) .. ":19000", + proxy_stream_error_log = "logs/error.log", + })) + end) + + before_each(function() + proxy_client = helpers.proxy_client() + end) + + after_each(function () + proxy_client:close() + end) + + lazy_teardown(function() + helpers.stop_kong() + end) + + it("use the deep copy of Service object", function() + for i = 1, 3 do + local tcp_client = ngx.socket.tcp() + assert(tcp_client:connect(helpers.get_proxy_ip(false), 19000)) + assert(tcp_client:send(MESSAGE)) + local body = assert(tcp_client:receive("*a")) + assert.equal(MESSAGE, body) + assert(tcp_client:close()) + end + end) + end) + end) +end