feat(core) execute subsequent phases upon short-circuited requests #3079

thibaultcha · 2017-12-08T05:03:28Z

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 plugins
running in the NGX_HTTP_LOG_PHASE would not be executed.

Arguably, this is an issue if one wishes to track such requests that are
short-circuited by Kong, i.e. via one of our available log plugins.

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:

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.
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.
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.

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.
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.
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 with the responses
module.
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

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 plugins running in the NGX_HTTP_LOG_PHASE would not be executed. Arguably, this is an issue if one wishes to track such requests that are short-circuited by Kong, i.e. via one of our available log plugins. 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 with the `responses` module. * 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 #2767 From #3079

p0pr0ck5 · 2017-12-08T17:19:26Z

@thibaultcha what are your thoughts on the following approach:

$ git diff
diff --git a/kong/init.lua b/kong/init.lua
index 861794a..d7fdccf 100644
--- a/kong/init.lua
+++ b/kong/init.lua
@@ -353,6 +353,7 @@ function Kong.access()
   core.access.before(ctx)
 
   ctx.delay_response = true
+  ctx.delayed_response_callback = responses.flush_delayed_response
 
   for plugin, plugin_conf in plugins_iterator(singletons.loaded_plugins, true) do
     if not ctx.delayed_response then
@@ -361,7 +362,7 @@ function Kong.access()
   end
 
   if ctx.delayed_response then
-    return responses.flush_delayed_response(ctx)
+    return ctx.delayed_response_callback(ctx)
   end

the idea here is that third party plugins could define their own callback function to execute a delayed response flush, instead of being tied into kong.tools.responses (which we keep as a default, so there is no functional behavior change in this diff). this aligns with the goals of the existing changeset (semi-unofficial API, minimal performance and code impact, no change to the plugins iterator) while giving third party devs the flexibility they may need. thoughts?

p0pr0ck5 · 2017-12-08T17:21:22Z

(This also has benefit of supporting the native request-termination plugin as well 👍 )

p0pr0ck5 · 2017-12-08T17:47:37Z

This is fleshed out a bit more at https://github.com/Kong/kong/tree/poc/pluggable-short-circuit, FWIW

p0pr0ck5 · 2017-12-08T20:33:25Z

kong/init.lua

  core.access.after(ctx)
 end

 function Kong.header_filter()
  local ctx = ngx.ctx
+
+  --[[


I'm having trouble understanding this comment. Assuming the comment code should not run, right? If so can we remove it and just have a human readable comment about the nature of this phase handler?

Those were for test purposes only and will be removed before merge - please ignore

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 #2767 From #3079

thibaultcha · 2017-12-08T22:08:22Z

@p0pr0ck5 Alright, I noted suggestion to take care of plugins who do not wish to use the responses module and added the necessary change (slightly different and with tests), and am finally satisfied with the current state of the patch. Let me know of any final thoughts you may have!

p0pr0ck5 · 2017-12-12T21:00:37Z

@thibaultcha only thought from me would be to update the PR message to match that git commit message, just for archaeology's sake.

thibaultcha · 2017-12-12T22:48:09Z

@p0pr0ck5 Yes, definitely

thibaultcha · 2017-12-12T22:48:40Z

In fact, commit message itself is to be updated - will ping for final approval

thibaultcha · 2017-12-12T23:22:28Z

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


Double checked that this is the only place in which we call responses.send() in between the ctx.delay_response = true assignment and the response flushing - it should be safe.

thibaultcha · 2017-12-12T23:24:57Z

FYI @thefosk

subnetmarco · 2017-12-12T23:26:32Z

@thibaultcha would this fix #892 ?

thibaultcha · 2017-12-12T23:27:06Z

@thefosk Yes - might have linked to the wrong issue here...

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

Work done in #3079 highlighted that tcp-log executed with a lower priority than request-termination. While this functionally has not presented a significant problem, this commit cleans up the prioritization of these plugins to a more sane definition. This has the added benefit of not requiring the request-termination define its own delayed callback function once #3079 is merged.

Work done in #3079 highlighted that tcp-log executed with a lower priority than request-termination. While this functionally has not presented a significant problem, this commit cleans up the prioritization of these plugins to a more sane definition. This has the added benefit of not requiring the request-termination define its own delayed callback function once #3079 is merged. From #3089

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

Work done in #3079 highlighted that tcp-log executed with a lower priority than request-termination. While this functionally has not presented a significant problem, this commit cleans up the prioritization of these plugins to a more sane definition. This has the added benefit of not requiring the request-termination define its own delayed callback function once #3079 is merged. From #3089

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

Context ------- Before this patch, several scenarios would make Kong/Nginx produce errors that did not execute plugins: 1. Nginx-produced client errors (HTTP 4xx) on invalid requests per the Nginx settings (e.g. headers too large, URI too large, etc...) 2. Proxy TCP/HTTP errors on the last balancer try (e.g. connection refused, connection timeout, read/write timeout, etc...) 3. Any other Nginx-produced server errors (HTTP 5xx), if any Because plugins are not executed in such cases, logging plugins in particular do not get a chance to report such errors, leaving Kong administrator blind when relying on bundled or homegrown logging plugins. Additionally, other plugins, e.g. transformation, do not get a chance to run either and could lead to scenarios where those errors produce headers or response bodies that are undesired by the administrator. This issue is similar to that fixed by #3079, which handled the following case: 4. Requests short-circuited by Kong itself (vs Nginx in 1, 2, and 3.) See also #490 & #892 for issues related to 4. This patches addresses 1, 2, and 3. Problem ------- Nginx-produced errors (4xx and 5xx) are redirected to the `/kong_error_handler` location by way of the `error_page` directive, but the runloop is not given a chance to run, since the error handler is only instructed to override the Nginx-defined HTML responses, and produces Kong-friendly ones. In short, a patch solving this issue must enable the runloop within the error handler. Proposed solution ----------------- Several (many) possibilities were evaluated and explored to fix this. The proposed patch is the result of many attempts, observations, and adjustments to initial proposals. In a gist, it proposes: * Executing the response part of the runloop in the error_page location. * Ensure that if the request part of the runloop did not have a chance to run, we do build the list of plugins to execute (thus, global plugins only since the request was not processed). * Ensure that if the request part of the runloop did run, we preserve its `ngx.ctx` values. A few catches: * Currently, `ngx.req.get_method()` in the `error_page` location block will return `GET` even if the request method was different (only `HEAD` is preserved). A follow up patch for Nginx is being prepared. As such, several tests are currently marked as "Pending". * When the `rewrite` phase did not get a chance to run, some parts of the request may not have been parsed by Nginx (e.g. on HTTP 414), thus some variables, such as `$request_uri` or request headers may not have been parsed. Code should be written defensively against such possibilities, and logging plugins may report incomplete request data (but will still report the produced error). * The `uninitialized_variable_warn` directive must be disabled in the `error_page` location block for cases when the `rewrite` phase did not get a chance to run (Nginx-produced 4xx clients errors). * The `ngx.ctx` variables must be copied by reference for plugins to be able to access it in the response phases when the request was short-circuited by Nginx (e.g. HTTP 502/504 from the upstream module). * Using a named location for the `error_page` handler is not possible, since in some cases the URI might not be parsed by Nginx, and thus Nginx refuses to call named locations in such cases (e.g. on HTTP 414). Resulting behavior ------------------ The `03-plugins_triggering_spec.lua` test suite is now a good reference for the behavior observed upon Nginx-produced errors. This behavior can be classified in 2 categories: 1. When the request is not parsed by Nginx (HTTP 4xx) a. The `error_page` directive is called (`rewrite` and `access` are skipped) b. The runloop retrieves the list of **global** plugins to run (it cannot retrieve more specific plugins since the request could not be parsed) c. The error content handler overrides the Nginx body with a Kong-friendly one (unchanged from previous behavior) d. It executes the `header_filter` phase of each global plugin. e. It executes the `body_filter` phase of each global plugin. f. It executes the `log` phase of each global plugin. 2. When the error was produced during upstream module execution (HTTP 5xx) a. The `rewrite` and `access` phases ran normally (we stashed the `ngx.ctx` reference) b. The `error_page` directive is called c. The error content handler applies the original `ngx.ctx` by reference d. It does **not** run the plugins loop, since `ngx.ctx` contains the list of plugins to run (global **and** specific plugins in this case) e. The error content handler overrides the Nginx body with a Kong-friendly one (unchanged from previous behavior) f. It executes the `header_filter` phase of each global plugin. g. It executes the `body_filter` phase of each global plugin. h. It executes the `log` phase of each global plugin. Fix #3193

Context ------- Before this patch, several scenarios would make Kong/Nginx produce errors that did not execute plugins: 1. Nginx-produced client errors (HTTP 4xx) on invalid requests per the Nginx settings (e.g. headers too large, URI too large, etc...) 2. Proxy TCP/HTTP errors on the last balancer try (e.g. connection refused, connection timeout, read/write timeout, etc...) 3. Any other Nginx-produced server errors (HTTP 5xx), if any Because plugins are not executed in such cases, logging plugins in particular do not get a chance to report such errors, leaving Kong administrator blind when relying on bundled or homegrown logging plugins. Additionally, other plugins, e.g. transformation, do not get a chance to run either and could lead to scenarios where those errors produce headers or response bodies that are undesired by the administrator. This issue is similar to that fixed by #3079, which handled the following case: 4. Requests short-circuited by Kong itself (vs Nginx in 1, 2, and 3.) See also #490 & #892 for issues related to 4. This patches addresses 1, 2, and 3. Problem ------- Nginx-produced errors (4xx and 5xx) are redirected to the `/kong_error_handler` location by way of the `error_page` directive, but the runloop is not given a chance to run, since the error handler is only instructed to override the Nginx-defined HTML responses, and produces Kong-friendly ones. In short, a patch solving this issue must enable the runloop within the error handler. Proposed solution ----------------- Several (many) possibilities were evaluated and explored to fix this. The proposed patch is the result of many attempts, observations, and adjustments to initial proposals. In a gist, it proposes: * Executing the response part of the runloop in the error_page location. * Ensure that if the request part of the runloop did not have a chance to run, we do build the list of plugins to execute (thus, global plugins only since the request was not processed). * Ensure that if the request part of the runloop did run, we preserve its `ngx.ctx` values. A few catches: * Currently, `ngx.req.get_method()` in the `error_page` location block will return `GET` even if the request method was different (only `HEAD` is preserved). A follow up patch for Nginx is being prepared. As such, several tests are currently marked as "Pending". * When the `rewrite` phase did not get a chance to run, some parts of the request may not have been parsed by Nginx (e.g. on HTTP 414), thus some variables, such as `$request_uri` or request headers may not have been parsed. Code should be written defensively against such possibilities, and logging plugins may report incomplete request data (but will still report the produced error). * The `uninitialized_variable_warn` directive must be disabled in the `error_page` location block for cases when the `rewrite` phase did not get a chance to run (Nginx-produced 4xx clients errors). * The `ngx.ctx` variables must be copied by reference for plugins to be able to access it in the response phases when the request was short-circuited by Nginx (e.g. HTTP 502/504 from the upstream module). * Using a named location for the `error_page` handler is not possible, since in some cases the URI might not be parsed by Nginx, and thus Nginx refuses to call named locations in such cases (e.g. on HTTP 414). Resulting behavior ------------------ The `03-plugins_triggering_spec.lua` test suite is now a good reference for the behavior observed upon Nginx-produced errors. This behavior can be classified in 2 categories: 1. When the request is not parsed by Nginx (HTTP 4xx) a. The `error_page` directive is called (`rewrite` and `access` are skipped) b. The runloop retrieves the list of **global** plugins to run (it cannot retrieve more specific plugins since the request could not be parsed) c. The error content handler overrides the Nginx body with a Kong-friendly one (unchanged from previous behavior) d. It executes the `header_filter` phase of each global plugin. e. It executes the `body_filter` phase of each global plugin. f. It executes the `log` phase of each global plugin. 2. When the error was produced during upstream module execution (HTTP 5xx) a. The `rewrite` and `access` phases ran normally (we stashed the `ngx.ctx` reference) b. The `error_page` directive is called c. The error content handler applies the original `ngx.ctx` by reference d. It does **not** run the plugins loop, since `ngx.ctx` contains the list of plugins to run (global **and** specific plugins in this case) e. The error content handler overrides the Nginx body with a Kong-friendly one (unchanged from previous behavior) f. It executes the `header_filter` phase of each global plugin. g. It executes the `body_filter` phase of each global plugin. h. It executes the `log` phase of each global plugin. Fix #3193 From #3533

Now the plugin does not short-circuit the runloop anymore. See #3079 From #3513

Now the plugin does not short-circuit the runloop anymore. See #3079 From #3512

thibaultcha added the pr/status/please review label Dec 8, 2017

thibaultcha force-pushed the feat/short-circuit-execute-log-phase branch from 4b5876e to 4f405e7 Compare December 8, 2017 05:18

thibaultcha force-pushed the feat/short-circuit-execute-log-phase branch from 4f405e7 to dcc0ce8 Compare December 8, 2017 05:29

thibaultcha added this to the 0.12.0 milestone Dec 8, 2017

p0pr0ck5 reviewed Dec 8, 2017

View reviewed changes

thibaultcha force-pushed the feat/short-circuit-execute-log-phase branch from dcc0ce8 to 09d4739 Compare December 8, 2017 21:49

thibaultcha force-pushed the feat/short-circuit-execute-log-phase branch from 09d4739 to 04b0ccd Compare December 12, 2017 22:49

thibaultcha changed the title ~~feat(core) execute log phase upon short-circuited requests~~ feat(core) execute subsequent phases upon short-circuited requests Dec 12, 2017

thibaultcha commented Dec 12, 2017

View reviewed changes

thibaultcha mentioned this pull request Dec 12, 2017

Kong latency headers not always displayed #2767

Closed

thibaultcha force-pushed the feat/short-circuit-execute-log-phase branch from 04b0ccd to 0ea49f8 Compare December 12, 2017 23:37

p0pr0ck5 mentioned this pull request Dec 12, 2017

fix(*) invert tcp-log and request-termination priority #3089

Merged

thibaultcha merged commit c6bde1a into next Dec 13, 2017

thibaultcha deleted the feat/short-circuit-execute-log-phase branch December 13, 2017 04:19

thibaultcha mentioned this pull request Jun 12, 2018

feat(runloop) execute plugins on Nginx-produced errors #3533

Merged

thibaultcha pushed a commit that referenced this pull request Jun 15, 2018

fix(request-termination) implement custom delayed response callback

1dea9ec

Now the plugin does not short-circuit the runloop anymore. See #3079 From #3513

thibaultcha pushed a commit that referenced this pull request Jun 15, 2018

fix(aws-lambda) implement custom delayed response callback

77ebd66

Now the plugin does not short-circuit the runloop anymore. See #3079 From #3512

thibaultcha mentioned this pull request Aug 14, 2018

enabling lambda functions to return custom status, body, and headers #3427

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(core) execute subsequent phases upon short-circuited requests #3079

feat(core) execute subsequent phases upon short-circuited requests #3079

thibaultcha commented Dec 8, 2017 •

edited

Loading

p0pr0ck5 commented Dec 8, 2017

p0pr0ck5 commented Dec 8, 2017

p0pr0ck5 commented Dec 8, 2017

p0pr0ck5 Dec 8, 2017

thibaultcha Dec 8, 2017

thibaultcha commented Dec 8, 2017

p0pr0ck5 commented Dec 12, 2017

thibaultcha commented Dec 12, 2017

thibaultcha commented Dec 12, 2017

thibaultcha Dec 12, 2017

thibaultcha commented Dec 12, 2017

subnetmarco commented Dec 12, 2017

thibaultcha commented Dec 12, 2017

feat(core) execute subsequent phases upon short-circuited requests #3079

feat(core) execute subsequent phases upon short-circuited requests #3079

Conversation

thibaultcha commented Dec 8, 2017 • edited Loading

Background context

Underlying issue

Possible solutions

Proposed solution

Changes

p0pr0ck5 commented Dec 8, 2017

p0pr0ck5 commented Dec 8, 2017

p0pr0ck5 commented Dec 8, 2017

p0pr0ck5 Dec 8, 2017

Choose a reason for hiding this comment

thibaultcha Dec 8, 2017

Choose a reason for hiding this comment

thibaultcha commented Dec 8, 2017

p0pr0ck5 commented Dec 12, 2017

thibaultcha commented Dec 12, 2017

thibaultcha commented Dec 12, 2017

thibaultcha Dec 12, 2017

Choose a reason for hiding this comment

thibaultcha commented Dec 12, 2017

subnetmarco commented Dec 12, 2017

thibaultcha commented Dec 12, 2017

thibaultcha commented Dec 8, 2017 •

edited

Loading