feat(runloop) execute plugins on Nginx-produced errors

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

kong-0.13.1-0.rockspec

@@ -60,6 +60,7 @@ build = {
     ["kong.templates.nginx_kong"] = "kong/templates/nginx_kong.lua",
     ["kong.templates.kong_defaults"] = "kong/templates/kong_defaults.lua",
 
+    ["kong.resty.ctx"] = "kong/resty/ctx.lua",
     ["kong.vendor.classic"] = "kong/vendor/classic.lua",
 
     ["kong.cmd"] = "kong/cmd/init.lua",

kong/init.lua

@@ -61,6 +61,7 @@ local singletons = require "kong.singletons"
 local DAOFactory = require "kong.dao.factory"
 local kong_cache = require "kong.cache"
 local ngx_balancer = require "ngx.balancer"
+local kong_resty_ctx = require "kong.resty.ctx"
 local plugins_iterator = require "kong.runloop.plugins_iterator"
 local balancer_execute = require("kong.runloop.balancer").execute
 local kong_cluster_events = require "kong.cluster_events"
@@ -383,6 +384,8 @@ function Kong.balancer()
 end
 
 function Kong.rewrite()
+  kong_resty_ctx.stash_ref()
+
   local ctx = ngx.ctx
   runloop.rewrite.before(ctx)
 
@@ -452,6 +455,14 @@ function Kong.log()
 end
 
 function Kong.handle_error()
+  kong_resty_ctx.apply_ref()
+
+  if not ngx.ctx.plugins_for_request then
+    for plugin, plugin_conf in plugins_iterator(singletons.loaded_plugins, true) do
+      -- just build list of plugins
+    end
+  end
+
   return kong_error_handlers(ngx)
 end
 

kong/plugins/log-serializers/basic.lua

@@ -13,10 +13,12 @@ function _M.serialize(ngx)
     }
   end
 
+  local request_uri = ngx.var.request_uri or ""
+
   return {
     request = {
-      uri = ngx.var.request_uri,
-      url = ngx.var.scheme .. "://" .. ngx.var.host .. ":" .. ngx.var.server_port .. ngx.var.request_uri,
+      uri = request_uri,
+      url = ngx.var.scheme .. "://" .. ngx.var.host .. ":" .. ngx.var.server_port .. request_uri,
       querystring = ngx.req.get_uri_args(), -- parameters, as a table
       method = ngx.req.get_method(), -- http method
       headers = ngx.req.get_headers(),

kong/resty/ctx.lua

@@ -0,0 +1,85 @@
+-- A module for sharing ngx.ctx between subrequests.
+-- Original work by Alex Zhang (openresty/lua-nginx-module/issues/1057)
+-- updated by 3scale/apicast.
+--
+-- Copyright (c) 2016 3scale Inc.
+-- Licensed under the Apache License, Version 2.0.
+-- License text: See LICENSE
+--
+-- Modifications by Kong Inc.
+--   * updated module functions signatures
+--   * made module function idempotent
+--   * replaced thrown errors with warn logs
+
+local ffi = require "ffi"
+local base = require "resty.core.base"
+
+
+local C = ffi.C
+local ngx = ngx
+local getfenv = getfenv
+local tonumber = tonumber
+local registry = debug.getregistry()
+
+
+local FFI_NO_REQ_CTX = base.FFI_NO_REQ_CTX
+
+
+local _M = {}
+
+
+function _M.stash_ref()
+  local r = getfenv(0).__ngx_req
+  if not r then
+    ngx.log(ngx.WARN, "could not stash ngx.ctx ref: no request found")
+    return
+  end
+
+  do
+    local ctx_ref = ngx.var.ctx_ref
+    if not ctx_ref or ctx_ref ~= "" then
+      return
+    end
+
+    local _ = ngx.ctx -- load context if not previously loaded
+  end
+
+  local ctx_ref = C.ngx_http_lua_ffi_get_ctx_ref(r)
+  if ctx_ref == FFI_NO_REQ_CTX then
+    ngx.log(ngx.WARN, "could not stash ngx.ctx ref: no ctx found")
+    return
+  end
+
+  ngx.var.ctx_ref = ctx_ref
+end
+
+
+function _M.apply_ref()
+  local r = getfenv(0).__ngx_req
+  if not r then
+    ngx.log(ngx.WARN, "could not apply ngx.ctx: no request found")
+    return
+  end
+
+  local ctx_ref = ngx.var.ctx_ref
+  if not ctx_ref or ctx_ref == "" then
+    return
+  end
+
+  ctx_ref = tonumber(ctx_ref)
+  if not ctx_ref then
+    return
+  end
+
+  local orig_ctx = registry.ngx_lua_ctx_tables[ctx_ref]
+  if not orig_ctx then
+    ngx.log(ngx.WARN, "could not apply ngx.ctx: no ctx found")
+    return
+  end
+
+  ngx.ctx = orig_ctx
+  ngx.var.ctx_ref = ""
+end
+
+
+return _M

kong/templates/nginx_kong.lua

@@ -112,6 +112,7 @@ server {
 > end
 
     location / {
+        set $ctx_ref                     '';
         set $upstream_host               '';
         set $upstream_upgrade            '';
         set $upstream_connection         '';
@@ -159,9 +160,23 @@ server {
 
     location = /kong_error_handler {
         internal;
+        uninitialized_variable_warn off;
+
         content_by_lua_block {
             kong.handle_error()
         }
+
+        header_filter_by_lua_block {
+            kong.header_filter()
+        }
+
+        body_filter_by_lua_block {
+            kong.body_filter()
+        }
+
+        log_by_lua_block {
+            kong.log()
+        }
     }
 }
 > end