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

@@ -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 {}

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
 

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

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
 

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)

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)

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

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
 
 

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" },
   }
 }