From 0ea49f8deecc6000e7f30fee6d0cbbb10de2c555 Mon Sep 17 00:00:00 2001 From: Thibault Charbonnier Date: Tue, 17 Oct 2017 15:02:43 -0700 Subject: [PATCH] feat(core) execute subsequent phases upon short-circuited requests Background context ------------------ Prior to this change, if a plugin short-circuits a request (e.g. auth plugin with HTTP 401, or rate limiting with HTTP 429) then subsequent plugins with a lower priority would not be executed by Kong. This is even more of an issue for logging plugins as they would be blind to requests short-circuited by Kong itself. The purpose of this patch is to allow other plugins in general to run after a plugin short-circuited a request in the access phase. Underlying issue ---------------- Our current plugins' run-loop is implemented in such a way that it both constructs the list of plugins to execute, and yields to its caller (for loop) at the same time. Once yielded, a plugin is instantly executed by the caller (for loop). If the plugin uses the `ngx.exit()` API, then the execution of the access phase is interrupted, and our run-loop never has the chance to add logging plugins to the list of plugins to execute for the current request (that is because logging plugins have a lower priority than our authentication plugins, which must run first). Possible solutions ------------------ One could think of several solutions to this issue: 1. Increase the priority of the logging plugins, so that they run earlier than auth plugin, and will be added to the list of plugins to execute for this request before the access phase is short-circuited. 2. Re-implement our run-loop (`plugins_iterator.lua` and `kong/init.lua`) so that it somehow builds the list of plugins to execute for a request first, then execute said plugin _after_. 3. Force the run-loop to rebuild the entire list of plugins inside of the logging phase. However, none of these solutions comes without a trade-off. 1. By updating the priority order of each plugin, we run the risk of unnecessarily breaking logic depending on the current order of execution. We also risk not fixing this issue for custom plugins without those plugins also bumping their priority order, which could cause cascading issues if other plugins depend on those plugins being executed at later phases. 2. While this is definitely a long-term goal, the breaking change nature of this solution should tell us that we would rather post-pone it until a better case study is made against it. Re-implementing our run-loop will benefit Kong in many ways (easier to write plugins, more fine-grained hooks, more sandboxing...), but doing so now would be disruptive for current plugins. One of this reasons behind this is that such a new run-loop should probably not follow the same paradigm of building itself and yielding at the same time. Instead, we should think of a run-loop executing global plugins first, then authentication plugins, then API/Consumer-specific plugin. Such an approach as of today would be extremely disruptive and break many assumptions made in existing plugins both defaults ones and in the wild. 3. The major flaw with this approach is that the run-loop depends on the datastore cache, which itself results in DB calls whenever a miss is encountered. However, relying on the datastore cache in the log phase is a very bad idea, since any sort of cache miss would trigger a DB request, which aren't supported in the log phase of NGINX due (rightfully so) to the lack of cosocket support in this phase. Proposed solution ----------------- This could be seen as a hack, or as a slightly more complex run-loop with some state. We take advantage of the fact that all of our plugins (and, very likely, most of third-party plugins out there) use the `responses` module to send their HTTP responses and short-circuit requests. The introduction of a flag in the request's context *delays* such a response, which gives the run-loop a chance to finish building the list of plugins to execute (but subsequent plugins do not run anymore once a plugin short-circuited the request). Once the list of plugins to execute is complete, we finally short-circuit the execution of the access phase, not giving Kong a chance to run the "after access" handler, thus not falsely leading other plugins into believe the request was proxied. Once the log phase kicks in, it will undoubtedly execute the registered plugins, even if their priority was lesser than that of the short-circuiting plugin. This way, we've achieved the desired result with minimal impact: * no plugin needs to update its `priority` constant * no plugin needs to see their code updated, as long as they use the `responses` module * the performance impact is minimal; we are only doing a few `ngx.ctx` accesses and there is no need to re-run the plugins iterators * the code change is minimal Changes ------- * Implemented a `ctx.delay_response` flag to play nice with the `responses` module. If set, we delay the flushing of the response until the plugins run-loop has finished running. Plugins can also make use of a custom flush callback for delayed response if they do not wish to use the `responses.send` API. They can do so by setting `ctx.delayed_response = true` and `ctx.delayed_response_callback` to a function accepting `ngx.ctx.` as its sole argument. * Ensure all plugins follow the correct pattern of always calling `responses.send()` with a `return` statement. * Implement regression tests for the subsequent-phases to run upon short-circuiting. Fix #490 Fix #892 From #3079 --- kong/core/plugins_iterator.lua | 3 +- kong/init.lua | 12 +- kong/plugins/acl/handler.lua | 2 +- kong/plugins/oauth2/access.lua | 15 +-- kong/tools/responses.lua | 27 ++++ spec/01-unit/009-responses_spec.lua | 68 +++++++++- .../05-proxy/03-plugins_triggering_spec.lua | 126 ++++++++++++++++++ .../kong/plugins/dummy/handler.lua | 13 ++ .../kong/plugins/dummy/schema.lua | 1 + 9 files changed, 254 insertions(+), 13 deletions(-) diff --git a/kong/core/plugins_iterator.lua b/kong/core/plugins_iterator.lua index 265a36afb5af..4a4ac9f07ba3 100644 --- a/kong/core/plugins_iterator.lua +++ b/kong/core/plugins_iterator.lua @@ -41,7 +41,8 @@ local function load_plugin_configuration(api_id, consumer_id, plugin_name) load_plugin_into_memory, api_id, consumer_id, plugin_name) if err then - responses.send_HTTP_INTERNAL_SERVER_ERROR(err) + ngx.ctx.delay_response = false + return responses.send_HTTP_INTERNAL_SERVER_ERROR(err) end if plugin ~= nil and plugin.enabled then return plugin.config or {} diff --git a/kong/init.lua b/kong/init.lua index 33a8ac297b71..c6d2e9b18511 100644 --- a/kong/init.lua +++ b/kong/init.lua @@ -352,10 +352,20 @@ function Kong.access() local ctx = ngx.ctx core.access.before(ctx) + ctx.delay_response = true + for plugin, plugin_conf in plugins_iterator(singletons.loaded_plugins, true) do - plugin.handler:access(plugin_conf) + if not ctx.delayed_response then + plugin.handler:access(plugin_conf) + end end + if ctx.delayed_response then + return responses.flush_delayed_response(ctx) + end + + ctx.delay_response = false + core.access.after(ctx) end diff --git a/kong/plugins/acl/handler.lua b/kong/plugins/acl/handler.lua index 761e38c7a404..70d924191a87 100644 --- a/kong/plugins/acl/handler.lua +++ b/kong/plugins/acl/handler.lua @@ -70,7 +70,7 @@ function ACLHandler:access(conf) local acls, err = singletons.cache:get(cache_key, nil, load_acls_into_memory, consumer_id) if err then - responses.send_HTTP_INTERNAL_SERVER_ERROR(err) + return responses.send_HTTP_INTERNAL_SERVER_ERROR(err) end if not acls then acls = EMPTY diff --git a/kong/plugins/oauth2/access.lua b/kong/plugins/oauth2/access.lua index c2465b2e342f..c47ab39d1768 100644 --- a/kong/plugins/oauth2/access.lua +++ b/kong/plugins/oauth2/access.lua @@ -543,17 +543,14 @@ function _M.execute(conf) if ngx.req.get_method() == "POST" then local uri = ngx.var.uri - local from, _ = string_find(uri, "/oauth2/token", nil, true) - + local from = string_find(uri, "/oauth2/token", nil, true) if from then - issue_token(conf) - - else - from, _ = string_find(uri, "/oauth2/authorize", nil, true) + return issue_token(conf) + end - if from then - authorize(conf) - end + from = string_find(uri, "/oauth2/authorize", nil, true) + if from then + return authorize(conf) end end diff --git a/kong/tools/responses.lua b/kong/tools/responses.lua index 51867805c76f..50c2d278ca54 100644 --- a/kong/tools/responses.lua +++ b/kong/tools/responses.lua @@ -21,6 +21,8 @@ local cjson = require "cjson.safe" local meta = require "kong.meta" +local type = type + --local server_header = _KONG._NAME .. "/" .. _KONG._VERSION local server_header = meta._NAME .. "/" .. meta._VERSION @@ -102,6 +104,18 @@ local function send_response(status_code) -- @param content (Optional) The content to send as a response. -- @return ngx.exit (Exit current context) return function(content, headers) + local ctx = ngx.ctx + + if ctx.delay_response and not ctx.delayed_response then + ctx.delayed_response = { + status_code = status_code, + content = content, + headers = headers, + } + + return + end + if status_code == _M.status_codes.HTTP_INTERNAL_SERVER_ERROR then if content then ngx.log(ngx.ERR, tostring(content)) @@ -137,6 +151,19 @@ local function send_response(status_code) end end +function _M.flush_delayed_response(ctx) + ctx.delay_response = false + + if type(ctx.delayed_response_callback) == "function" then + ctx.delayed_response_callback(ctx) + return -- avoid tail call + end + + _M.send(ctx.delayed_response.status_code, + ctx.delayed_response.content, + ctx.delayed_response.headers) +end + -- Generate sugar methods (closures) for the most used HTTP status codes. for status_code_name, status_code in pairs(_M.status_codes) do _M["send_" .. status_code_name] = send_response(status_code) diff --git a/spec/01-unit/009-responses_spec.lua b/spec/01-unit/009-responses_spec.lua index 04db5ac221ff..7fe313ecf31f 100644 --- a/spec/01-unit/009-responses_spec.lua +++ b/spec/01-unit/009-responses_spec.lua @@ -61,7 +61,7 @@ describe("Response helpers", function() it("calls `ngx.log` if and only if a 500 status code was given", function() responses.send_HTTP_BAD_REQUEST() assert.stub(ngx.log).was_not_called() - + responses.send_HTTP_BAD_REQUEST("error") assert.stub(ngx.log).was_not_called() @@ -119,4 +119,70 @@ describe("Response helpers", function() assert.stub(ngx.exit).was.called_with(501) end) end) + + describe("delayed response", function() + it("does not call ngx.say/ngx.exit if `ctx.delayed_response = true`", function() + ngx.ctx.delay_response = true + + responses.send(401, "Unauthorized", { ["X-Hello"] = "world" }) + assert.stub(ngx.say).was_not_called() + assert.stub(ngx.exit).was_not_called() + assert.not_equal("world", ngx.header["X-Hello"]) + end) + + it("flush_delayed_response() sends delayed response's status/header/body", function() + ngx.ctx.delay_response = true + + responses.send(401, "Unauthorized", { ["X-Hello"] = "world" }) + responses.flush_delayed_response(ngx.ctx) + + assert.stub(ngx.say).was.called_with("{\"message\":\"Unauthorized\"}") + assert.stub(ngx.exit).was.called_with(401) + assert.equal("world", ngx.header["X-Hello"]) + assert.is_false(ngx.ctx.delay_response) + end) + + it("delayed response cannot be overriden", function() + ngx.ctx.delay_response = true + + responses.send(401, "Unauthorized") + responses.send(200, "OK") + responses.flush_delayed_response(ngx.ctx) + + assert.stub(ngx.say).was.called_with("{\"message\":\"Unauthorized\"}") + assert.stub(ngx.exit).was.called_with(401) + end) + + it("flush_delayed_response() use custom callback if set", function() + local s = spy.new(function(ctx) end) + + do + local old_type = _G.type + + -- luacheck: ignore + _G.type = function(v) + if v == s then + return "function" + end + + return old_type(v) + end + + finally(function() + _G.type = old_type + end) + end + + package.loaded["kong.tools.responses"] = nil + responses = require "kong.tools.responses" + + ngx.ctx.delay_response = true + ngx.ctx.delayed_response_callback = s + + responses.send(401, "Unauthorized", { ["X-Hello"] = "world" }) + responses.flush_delayed_response(ngx.ctx) + + assert.spy(s).was.called_with(ngx.ctx) + end) + end) end) diff --git a/spec/02-integration/05-proxy/03-plugins_triggering_spec.lua b/spec/02-integration/05-proxy/03-plugins_triggering_spec.lua index 2b2ebfc19167..1abe01896d3e 100644 --- a/spec/02-integration/05-proxy/03-plugins_triggering_spec.lua +++ b/spec/02-integration/05-proxy/03-plugins_triggering_spec.lua @@ -165,6 +165,132 @@ describe("Plugins triggering", function() assert.equal("5", res.headers["x-ratelimit-limit-hour"]) end) + describe("short-circuited requests", function() + local FILE_LOG_PATH = os.tmpname() + + setup(function() + if client then + client:close() + end + + helpers.stop_kong() + helpers.dao:truncate_tables() + + local api = assert(helpers.dao.apis:insert { + name = "example", + hosts = { "mock_upstream" }, + upstream_url = helpers.mock_upstream_url, + }) + + -- plugin able to short-circuit a request + assert(helpers.dao.plugins:insert { + name = "key-auth", + api_id = api.id, + }) + + -- response/body filter plugin + assert(helpers.dao.plugins:insert { + name = "dummy", + api_id = api.id, + config = { + append_body = "appended from body filtering", + } + }) + + -- log phase plugin + assert(helpers.dao.plugins:insert { + name = "file-log", + api_id = api.id, + config = { + path = FILE_LOG_PATH, + }, + }) + + assert(helpers.start_kong { + nginx_conf = "spec/fixtures/custom_nginx.template", + }) + + client = helpers.proxy_client() + end) + + teardown(function() + if client then + client:close() + end + + os.remove(FILE_LOG_PATH) + + helpers.stop_kong() + end) + + it("execute a log plugin", function() + local utils = require "kong.tools.utils" + local cjson = require "cjson" + local pl_path = require "pl.path" + local pl_file = require "pl.file" + local pl_stringx = require "pl.stringx" + + local uuid = utils.uuid() + + local res = assert(client:send { + method = "GET", + path = "/status/200", + headers = { + ["Host"] = "mock_upstream", + ["X-UUID"] = uuid, + -- /!\ no key credential + } + }) + assert.res_status(401, res) + + -- TEST: ensure that our logging plugin was executed and wrote + -- something to disk. + + helpers.wait_until(function() + return pl_path.exists(FILE_LOG_PATH) and pl_path.getsize(FILE_LOG_PATH) > 0 + end, 3) + + local log = pl_file.read(FILE_LOG_PATH) + local log_message = cjson.decode(pl_stringx.strip(log)) + assert.equal("127.0.0.1", log_message.client_ip) + assert.equal(uuid, log_message.request.headers["x-uuid"]) + end) + + it("execute a header_filter plugin", function() + local res = assert(client:send { + method = "GET", + path = "/status/200", + headers = { + ["Host"] = "mock_upstream", + } + }) + assert.res_status(401, res) + + -- TEST: ensure that the dummy plugin was executed by checking + -- that headers have been injected in the header_filter phase + -- Plugins such as CORS need to run on short-circuited requests + -- as well. + + assert.not_nil(res.headers["dummy-plugin"]) + end) + + it("execute a body_filter plugin", function() + local res = assert(client:send { + method = "GET", + path = "/status/200", + headers = { + ["Host"] = "mock_upstream", + } + }) + local body = assert.res_status(401, res) + + -- TEST: ensure that the dummy plugin was executed by checking + -- that the body filtering phase has run + + assert.matches("appended from body filtering", body, nil, true) + end) + end) + describe("anonymous reports execution", function() -- anonymous reports are implemented as a plugin which is being executed -- by the plugins runloop, but which doesn't have a schema diff --git a/spec/fixtures/custom_plugins/kong/plugins/dummy/handler.lua b/spec/fixtures/custom_plugins/kong/plugins/dummy/handler.lua index 6d7e208ac62e..d60b899dcea0 100644 --- a/spec/fixtures/custom_plugins/kong/plugins/dummy/handler.lua +++ b/spec/fixtures/custom_plugins/kong/plugins/dummy/handler.lua @@ -21,6 +21,19 @@ function DummyHandler:header_filter(conf) DummyHandler.super.header_filter(self) ngx.header["Dummy-Plugin"] = conf.resp_header_value + + if conf.append_body then + ngx.header["Content-Length"] = nil + end +end + + +function DummyHandler:body_filter(conf) + DummyHandler.super.body_filter(self) + + if conf.append_body and not ngx.arg[2] then + ngx.arg[1] = string.sub(ngx.arg[1], 1, -2) .. conf.append_body + end end diff --git a/spec/fixtures/custom_plugins/kong/plugins/dummy/schema.lua b/spec/fixtures/custom_plugins/kong/plugins/dummy/schema.lua index ccee388296a2..b193b332fe39 100644 --- a/spec/fixtures/custom_plugins/kong/plugins/dummy/schema.lua +++ b/spec/fixtures/custom_plugins/kong/plugins/dummy/schema.lua @@ -1,5 +1,6 @@ return { fields = { resp_header_value = { type = "string", default = "1" }, + append_body = { type = "string" }, } }