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