From e709c953933e5ca6f6e9766fde15d8fe98a80721 Mon Sep 17 00:00:00 2001 From: Thibault Charbonnier Date: Thu, 14 Jun 2018 20:15:51 -0700 Subject: [PATCH] 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 | 1 + kong/init.lua | 11 + kong/plugins/log-serializers/basic.lua | 6 +- kong/resty/ctx.lua | 85 +++ kong/templates/nginx_kong.lua | 15 + .../05-proxy/03-plugins_triggering_spec.lua | 494 +++++++++++++++++- .../05-proxy/11-error_default_type_spec.lua | 12 +- spec/fixtures/custom_nginx.template | 17 +- .../plugins/error-handler-log/handler.lua | 55 ++ .../kong/plugins/error-handler-log/schema.lua | 3 + spec/helpers.lua | 2 +- 11 files changed, 685 insertions(+), 16 deletions(-) create mode 100644 kong/resty/ctx.lua create mode 100644 spec/fixtures/custom_plugins/kong/plugins/error-handler-log/handler.lua create mode 100644 spec/fixtures/custom_plugins/kong/plugins/error-handler-log/schema.lua diff --git a/kong-0.13.1-0.rockspec b/kong-0.13.1-0.rockspec index 9e56e7bb72b..f698b14245b 100644 --- a/kong-0.13.1-0.rockspec +++ b/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", diff --git a/kong/init.lua b/kong/init.lua index e6d6639be1b..dd3fd39138d 100644 --- a/kong/init.lua +++ b/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 diff --git a/kong/plugins/log-serializers/basic.lua b/kong/plugins/log-serializers/basic.lua index e63c49660ab..a5876f7a7cd 100644 --- a/kong/plugins/log-serializers/basic.lua +++ b/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(), diff --git a/kong/resty/ctx.lua b/kong/resty/ctx.lua new file mode 100644 index 00000000000..15d3f4d68dd --- /dev/null +++ b/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 diff --git a/kong/templates/nginx_kong.lua b/kong/templates/nginx_kong.lua index 0f86d109b6f..b01d9ab8073 100644 --- a/kong/templates/nginx_kong.lua +++ b/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 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 ba538133297..a566ff27de2 100644 --- a/spec/02-integration/05-proxy/03-plugins_triggering_spec.lua +++ b/spec/02-integration/05-proxy/03-plugins_triggering_spec.lua @@ -1,4 +1,9 @@ local helpers = require "spec.helpers" +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" for _, strategy in helpers.each_strategy() do @@ -311,12 +316,6 @@ for _, strategy in helpers.each_strategy() do 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(proxy_client:send { @@ -379,11 +378,6 @@ for _, strategy in helpers.each_strategy() do -- regression test for bug spotted in 0.12.0rc2 it("responses.send stops plugin but runloop continues", 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(proxy_client:send { @@ -506,5 +500,483 @@ for _, strategy in helpers.each_strategy() do assert.res_status(200, res) end) end) + + describe("proxy-intercepted error", function() + local FILE_LOG_PATH = os.tmpname() + + + setup(function() + assert(db:truncate()) + dao:truncate_tables() + + do + -- service to mock HTTP 502 + local mock_service = bp.services:insert { + name = "conn_refused", + host = "127.0.0.2", + port = 26865, + } + + bp.routes:insert { + hosts = { "refused" }, + protocols = { "http" }, + service = mock_service, + } + + bp.plugins:insert { + name = "file-log", + service_id = mock_service.id, + config = { + path = FILE_LOG_PATH, + reopen = true, + } + } + end + + do + -- service to mock HTTP 503 + local mock_service = bp.services:insert { + name = "unavailable", + } + + bp.routes:insert { + hosts = { "unavailable" }, + protocols = { "http" }, + service = mock_service, + } + + bp.plugins:insert { + name = "file-log", + service_id = mock_service.id, + config = { + path = FILE_LOG_PATH, + reopen = true, + } + } + end + + do + -- service to mock HTTP 504 + local httpbin_service = bp.services:insert { + name = "timeout", + host = "httpbin.org", + connect_timeout = 1, -- ms + } + + bp.routes:insert { + hosts = { "connect_timeout" }, + protocols = { "http" }, + service = httpbin_service, + } + + bp.plugins:insert { + name = "file-log", + service_id = httpbin_service.id, + config = { + path = FILE_LOG_PATH, + reopen = true, + } + } + end + + do + -- global plugin to catch Nginx-produced client errors + bp.plugins:insert { + name = "file-log", + config = { + path = FILE_LOG_PATH, + reopen = true, + } + } + + bp.plugins:insert { + name = "error-handler-log", + config = {}, + } + end + + -- start mock httpbin instance + assert(helpers.start_kong { + database = strategy, + admin_listen = "127.0.0.1:9011", + proxy_listen = "127.0.0.1:9010", + proxy_listen_ssl = "127.0.0.1:9453", + admin_listen_ssl = "127.0.0.1:9454", + prefix = "servroot2", + nginx_conf = "spec/fixtures/custom_nginx.template", + }) + + -- start Kong instance with our services and plugins + assert(helpers.start_kong { + database = strategy, + -- /!\ test with real nginx config + }) + end) + + + teardown(function() + helpers.stop_kong("servroot2") + helpers.stop_kong() + end) + + + before_each(function() + proxy_client = helpers.proxy_client() + end) + + + after_each(function() + pl_file.delete(FILE_LOG_PATH) + + if proxy_client then + proxy_client:close() + end + end) + + + it("executes a log plugin on Bad Gateway (HTTP 502)", function() + -- triggers error_page directive + local uuid = utils.uuid() + + local res = assert(proxy_client:send { + method = "GET", + path = "/status/200", + headers = { + ["Host"] = "refused", + ["X-UUID"] = uuid, + } + }) + assert.res_status(502, res) -- Bad Gateway + + -- 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) + + + pending("log plugins sees same request in error_page handler (HTTP 502)", function() + -- PENDING: waiting on Nginx error_patch_preserve_method patch + + -- triggers error_page directive + local uuid = utils.uuid() + + local res = assert(proxy_client:send { + method = "POST", + path = "/status/200?foo=bar", + headers = { + ["Host"] = "refused", + ["X-UUID"] = uuid, + }, + --[[ file-log plugin does not log request body + body = { + hello = "world", + } + --]] + }) + assert.res_status(502, res) -- Bad Gateway + + -- 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(uuid, log_message.request.headers["x-uuid"]) + assert.equal("refused", log_message.request.headers.host) + assert.equal("POST", log_message.request.method) + assert.equal("bar", log_message.request.querystring.foo) + assert.equal("/status/200?foo=bar", log_message.upstream_uri) + end) + + + it("executes a log plugin on Service Unavailable (HTTP 503)", function() + -- Does not trigger error_page directive (no proxy_intercept_errors) + local uuid = utils.uuid() + + local res = assert(proxy_client:send { + method = "GET", + path = "/status/503", + headers = { + ["Host"] = "unavailable", + ["X-UUID"] = uuid, + } + }) + assert.res_status(503, res) -- Service Unavailable + + -- 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("executes a log plugin on Gateway Timeout (HTTP 504)", function() + -- triggers error_page directive + local uuid = utils.uuid() + + local res = assert(proxy_client:send { + method = "GET", + path = "/status/200", + headers = { + ["Host"] = "connect_timeout", + ["X-UUID"] = uuid, + } + }) + assert.res_status(504, res) -- Gateway Timeout + + -- 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) + + + pending("log plugins sees same request in error_page handler (HTTP 504)", function() + -- triggers error_page directive + local uuid = utils.uuid() + + local res = assert(proxy_client:send { + method = "POST", + path = "/status/200?foo=bar", + headers = { + ["Host"] = "connect_timeout", + ["X-UUID"] = uuid, + }, + --[[ file-log plugin does not log request body + body = { + hello = "world", + } + --]] + }) + assert.res_status(504, res) -- Gateway Timeout + + -- 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(uuid, log_message.request.headers["x-uuid"]) + assert.equal("connect_timeout", log_message.request.headers.host) + assert.equal("POST", log_message.request.method) + assert.equal("bar", log_message.request.querystring.foo) + assert.equal("/status/200?foo=bar", log_message.upstream_uri) + end) + + + it("executes a global log plugin on Nginx-produced client errors (HTTP 494)", function() + -- triggers error_page directive + local uuid = utils.uuid() + + local res = assert(proxy_client:send { + method = "GET", + path = "/", + headers = { + ["Host"] = "unavailable", + ["X-Large"] = string.rep("a", 2^10 * 10), -- default large_client_header_buffers is 8k + ["X-UUID"] = uuid, + } + }) + assert.res_status(494, 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, 10) + + local log = pl_file.read(FILE_LOG_PATH) + local log_message = cjson.decode(pl_stringx.strip(log)) + + assert.equal(uuid, log_message.request.headers["x-uuid"]) + assert.equal(494, log_message.response.status) + end) + + + pending("log plugins sees same request in error_page handler (HTTP 494)", function() + -- PENDING: waiting on Nginx error_patch_preserve_method patch + + -- triggers error_page directive + local uuid = utils.uuid() + + local res = assert(proxy_client:send { + method = "POST", + path = "/status/200?foo=bar", + headers = { + ["Host"] = "unavailable", + ["X-Large"] = string.rep("a", 2^10 * 10), -- default large_client_header_buffers is 8k + ["X-UUID"] = uuid, + }, + --[[ file-log plugin does not log request body + body = { + hello = "world", + } + --]] + }) + assert.res_status(494, 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, 10) + + local log = pl_file.read(FILE_LOG_PATH) + local log_message = cjson.decode(pl_stringx.strip(log)) + assert.equal("POST", log_message.request.method) + assert.equal("bar", log_message.request.querystring.foo) + assert.equal("/status/200?foo=bar", log_message.upstream_uri) + assert.equal(uuid, log_message.request.headers["x-uuid"]) + assert.equal("unavailable", log_message.request.headers.host) + end) + + + it("executes a global log plugin on Nginx-produced client errors (HTTP 414)", function() + -- triggers error_page directive + local uuid = utils.uuid() + + local res = assert(proxy_client:send { + method = "GET", + path = "/?foo=" .. string.rep("a", 2^10 * 10), + headers = { + ["Host"] = "unavailable", + ["X-UUID"] = uuid, + } + }) + assert.res_status(414, 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, 10) + + local log = pl_file.read(FILE_LOG_PATH) + local log_message = cjson.decode(pl_stringx.strip(log)) + + assert.same({}, log_message.request.headers) + assert.equal(414, log_message.response.status) + end) + + + pending("log plugins sees same request in error_page handler (HTTP 414)", function() + -- PENDING: waiting on Nginx error_patch_preserve_method patch + + -- triggers error_page directive + local uuid = utils.uuid() + + local res = assert(proxy_client:send { + method = "POST", + path = "/?foo=" .. string.rep("a", 2^10 * 10), + headers = { + ["Host"] = "unavailable", + ["X-UUID"] = uuid, + }, + --[[ file-log plugin does not log request body + body = { + hello = "world", + } + --]] + }) + assert.res_status(414, 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, 10) + + local log = pl_file.read(FILE_LOG_PATH) + local log_message = cjson.decode(pl_stringx.strip(log)) + local ins = require "inspect" + print(ins(log_message)) + assert.equal("POST", log_message.request.method) + assert.equal("", log_message.upstream_uri) -- no URI here since Nginx could not parse request + assert.is_nil(log_message.request.headers["x-uuid"]) -- none since Nginx could not parse request + assert.is_nil(log_message.request.headers.host) -- none as well + end) + + + it("executes plugins header_filter/body_filter on Nginx-produced client errors (HTTP 4xx)", function() + local res = assert(proxy_client:send { + method = "GET", + path = "/?foo=" .. string.rep("a", 2^10 * 10), + headers = { + ["Host"] = "unavailable", + } + }) + local body = assert.res_status(414, res) + assert.equal("header_filter", res.headers["Log-Plugin-Phases"]) + assert.equal("body_filter", body) + end) + + + it("executes plugins header_filter/body_filter on Nginx-produced server errors (HTTP 5xx)", function() + local res = assert(proxy_client:send { + method = "GET", + path = "/status/200", + headers = { + ["Host"] = "connect_timeout", + } + }) + local body = assert.res_status(504, res) -- Gateway Timeout + assert.equal("rewrite,access,header_filter", res.headers["Log-Plugin-Phases"]) -- rewrite + acecss from original request handling + assert.equal("body_filter", body) + end) + + + it("sees ctx introspection variables on Nginx-produced server errors (HTTP 5xx)", function() + local res = assert(proxy_client:send { + method = "GET", + path = "/status/200", + headers = { + ["Host"] = "connect_timeout", + } + }) + assert.res_status(504, res) -- Gateway Timeout + assert.equal("timeout", res.headers["Log-Plugin-Service-Matched"]) + end) + end) end) end diff --git a/spec/02-integration/05-proxy/11-error_default_type_spec.lua b/spec/02-integration/05-proxy/11-error_default_type_spec.lua index 5b72e875021..3ef4ae513ec 100644 --- a/spec/02-integration/05-proxy/11-error_default_type_spec.lua +++ b/spec/02-integration/05-proxy/11-error_default_type_spec.lua @@ -21,7 +21,7 @@ for _, strategy in helpers.each_strategy() do } bp.routes:insert { - methods = { "GET" }, + methods = { "GET", "HEAD" }, service = service, } @@ -64,6 +64,16 @@ for _, strategy in helpers.each_strategy() do assert.equal(html_message, body) end) + it("HEAD request does not return a body", function() + local res = assert(proxy_client:send { + method = "HEAD", + path = "/", + }) + + local body = assert.res_status(RESPONSE_CODE, res) + assert.equal("", body) + end) + describe("", function() setup(function() assert(helpers.kong_exec(("restart --conf %s --nginx-conf %s"):format( diff --git a/spec/fixtures/custom_nginx.template b/spec/fixtures/custom_nginx.template index 9aafc2b5fb0..1295e67c880 100644 --- a/spec/fixtures/custom_nginx.template +++ b/spec/fixtures/custom_nginx.template @@ -113,8 +113,9 @@ http { > end location / { - default_type ''; + default_type ''; + set $ctx_ref ''; set $upstream_host ''; set $upstream_upgrade ''; set $upstream_connection ''; @@ -162,9 +163,23 @@ http { 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 diff --git a/spec/fixtures/custom_plugins/kong/plugins/error-handler-log/handler.lua b/spec/fixtures/custom_plugins/kong/plugins/error-handler-log/handler.lua new file mode 100644 index 00000000000..92d6142a85e --- /dev/null +++ b/spec/fixtures/custom_plugins/kong/plugins/error-handler-log/handler.lua @@ -0,0 +1,55 @@ +local BasePlugin = require "kong.plugins.base_plugin" + + +local ErrHandlerLog = BasePlugin:extend() + + +ErrHandlerLog.PRIORITY = 1000 + + +function ErrHandlerLog:new() + ErrHandlerLog.super.new(self, "error-handler-log") +end + + +function ErrHandlerLog:rewrite(conf) + ErrHandlerLog.super.rewrite(self) + + local phases = ngx.ctx.err_handler_log_phases or {} + table.insert(phases, "rewrite") + ngx.ctx.err_handler_log_phases = phases +end + + +function ErrHandlerLog:access(conf) + ErrHandlerLog.super.access(self) + + local phases = ngx.ctx.err_handler_log_phases or {} + table.insert(phases, "access") + ngx.ctx.err_handler_log_phases = phases +end + + +function ErrHandlerLog:header_filter(conf) + ErrHandlerLog.super.header_filter(self) + + local phases = ngx.ctx.err_handler_log_phases or {} + table.insert(phases, "header_filter") + + ngx.header["Content-Length"] = nil + ngx.header["Log-Plugin-Phases"] = table.concat(phases, ",") + + ngx.header["Log-Plugin-Service-Matched"] = ngx.ctx.service and ngx.ctx.service.name +end + + +function ErrHandlerLog:body_filter(conf) + ErrHandlerLog.super.body_filter(self) + + if not ngx.arg[2] then + ngx.arg[1] = "body_filter" + end +end + + +return ErrHandlerLog diff --git a/spec/fixtures/custom_plugins/kong/plugins/error-handler-log/schema.lua b/spec/fixtures/custom_plugins/kong/plugins/error-handler-log/schema.lua new file mode 100644 index 00000000000..8b6db5093d1 --- /dev/null +++ b/spec/fixtures/custom_plugins/kong/plugins/error-handler-log/schema.lua @@ -0,0 +1,3 @@ +return { + fields = {} +} diff --git a/spec/helpers.lua b/spec/helpers.lua index 454a8d4d645..e202ce88909 100644 --- a/spec/helpers.lua +++ b/spec/helpers.lua @@ -1013,7 +1013,7 @@ local function kong_exec(cmd, env) env.lua_package_path = env.lua_package_path .. ";" .. conf.lua_package_path if not env.plugins then - env.plugins = "bundled,dummy,cache,rewriter" + env.plugins = "bundled,dummy,cache,rewriter,error-handler-log" end -- build Kong environment variables