fix(log-serializer) log correct request properties on NGINX-produced errors

kong/pdk/init.lua

@@ -211,7 +211,7 @@ assert(package.loaded["resty.core"])
 
 local MAJOR_VERSIONS = {
   [1] = {
-    version = "1.2.0",
+    version = "1.3.0",
     modules = {
       "table",
       "node",

kong/pdk/request.lua

@@ -264,6 +264,14 @@ local function new(self)
   function _REQUEST.get_method()
     check_phase(PHASES.request)
 
+    if ngx.ctx.KONG_UNEXPECTED and _REQUEST.get_http_version() < 2 then
+      local req_line = ngx.var.request
+      local idx = find(req_line, " ", 1, true)
+      if idx then
+        return sub(req_line, 1, idx - 1)
+      end
+    end
+
     return ngx.req.get_method()
   end
 
@@ -397,19 +405,36 @@ local function new(self)
     check_phase(PHASES.request)
 
     if max_args == nil then
-      return ngx.req.get_uri_args(MAX_QUERY_ARGS_DEFAULT)
-    end
+      max_args = MAX_QUERY_ARGS_DEFAULT
 
-    if type(max_args) ~= "number" then
-      error("max_args must be a number", 2)
-    end
+    else
+      if type(max_args) ~= "number" then
+        error("max_args must be a number", 2)
+      end
 
-    if max_args < MIN_QUERY_ARGS then
-      error("max_args must be >= " .. MIN_QUERY_ARGS, 2)
+      if max_args < MIN_QUERY_ARGS then
+        error("max_args must be >= " .. MIN_QUERY_ARGS, 2)
+      end
+
+      if max_args > MAX_QUERY_ARGS then
+        error("max_args must be <= " .. MAX_QUERY_ARGS, 2)
+      end
     end
 
-    if max_args > MAX_QUERY_ARGS then
-      error("max_args must be <= " .. MAX_QUERY_ARGS, 2)
+    if ngx.ctx.KONG_UNEXPECTED and _REQUEST.get_http_version() < 2 then
+      local req_line = ngx.var.request
+      local qidx = find(req_line, "?", 1, true)
+      if not qidx then
+        return {}
+      end
+
+      local eidx = find(req_line, " ", qidx + 1, true)
+      if not eidx then
+        -- HTTP 414, req_line is too long
+        return {}
+      end
+
+      return ngx.decode_args(sub(req_line, qidx + 1, eidx - 1), max_args)
     end
 
     return ngx.req.get_uri_args(max_args)

kong/plugins/log-serializers/basic.lua

@@ -1,15 +1,20 @@
 local tablex = require "pl.tablex"
 local ngx_ssl = require "ngx.ssl"
+local gkong = kong
 
 local _M = {}
 
 local EMPTY = tablex.readonly({})
 
-function _M.serialize(ngx)
+function _M.serialize(ngx, kong)
   local ctx = ngx.ctx
   local var = ngx.var
   local req = ngx.req
 
+  if not kong then
+    kong = gkong
+  end
+
   local authenticated_entity
   if ctx.authenticated_credential ~= nil then
     authenticated_entity = {
@@ -34,9 +39,9 @@ function _M.serialize(ngx)
     request = {
       uri = request_uri,
       url = var.scheme .. "://" .. var.host .. ":" .. var.server_port .. request_uri,
-      querystring = req.get_uri_args(), -- parameters, as a table
-      method = req.get_method(), -- http method
-      headers = req.get_headers(),
+      querystring = kong.request.get_query(), -- parameters, as a table
+      method = kong.request.get_method(), -- http method
+      headers = kong.request.get_headers(),
       size = var.request_length,
       tls = request_tls
     },

spec/01-unit/10-log_serializer_spec.lua

@@ -1,10 +1,9 @@
+require "spec.helpers"
 local basic = require "kong.plugins.log-serializers.basic"
 
 describe("Log Serializer", function()
-  local ngx
-
   before_each(function()
-    ngx = {
+    _G.ngx = {
       ctx = {
         balancer_data = {
           tries = {
@@ -36,11 +35,15 @@ describe("Log Serializer", function()
         get_headers = function() return {"respheader1", "respheader2"} end
       }
     }
+
+    package.loaded["kong.pdk.request"] = nil
+    local pdk_request = require "kong.pdk.request"
+    kong.request = pdk_request.new(kong)
   end)
 
   describe("Basic", function()
     it("serializes without API, Consumer or Authenticated entity", function()
-      local res = basic.serialize(ngx)
+      local res = basic.serialize(ngx, kong)
       assert.is_table(res)
 
       -- Simple properties
@@ -80,7 +83,7 @@ describe("Log Serializer", function()
       ngx.ctx.route = { id = "my_route" }
       ngx.ctx.service = { id = "my_service" }
 
-      local res = basic.serialize(ngx)
+      local res = basic.serialize(ngx, kong)
       assert.is_table(res)
 
       assert.equal("my_route", res.route.id)
@@ -92,7 +95,7 @@ describe("Log Serializer", function()
     it("serializes the Consumer object", function()
       ngx.ctx.authenticated_consumer = {id = "someconsumer"}
 
-      local res = basic.serialize(ngx)
+      local res = basic.serialize(ngx, kong)
       assert.is_table(res)
 
       assert.equal("someconsumer", res.consumer.id)
@@ -104,7 +107,7 @@ describe("Log Serializer", function()
       ngx.ctx.authenticated_credential = {id = "somecred",
                                           consumer_id = "user1"}
 
-      local res = basic.serialize(ngx)
+      local res = basic.serialize(ngx, kong)
       assert.is_table(res)
 
       assert.same({id = "somecred", consumer_id = "user1"},
@@ -120,7 +123,7 @@ describe("Log Serializer", function()
         { ip = "127.0.0.1", port = 1234 },
       }
 
-      local res = basic.serialize(ngx)
+      local res = basic.serialize(ngx, kong)
       assert.is_table(res)
 
       assert.same({
@@ -143,7 +146,7 @@ describe("Log Serializer", function()
     it("does not fail when the 'balancer_data' structure is missing", function()
       ngx.ctx.balancer_data = nil
 
-      local res = basic.serialize(ngx)
+      local res = basic.serialize(ngx, kong)
       assert.is_table(res)
 
       assert.is_nil(res.tries)

spec/02-integration/05-proxy/04-plugins_triggering_spec.lua

@@ -694,9 +694,7 @@ for _, strategy in helpers.each_strategy() do
       end)
 
 
-      pending("log plugins sees same request in error_page handler (HTTP 502)", function()
-        -- PENDING: waiting on Nginx error_patch_preserve_method patch
-
+      it("log plugins sees same request in error_page handler (HTTP 502)", function()
         -- triggers error_page directive
         local uuid = utils.uuid()
 
@@ -791,7 +789,7 @@ for _, strategy in helpers.each_strategy() do
       end)
 
 
-      pending("log plugins sees same request in error_page handler (HTTP 504)", function()
+      it("log plugins sees same request in error_page handler (HTTP 504)", function()
         -- triggers error_page directive
         local uuid = utils.uuid()
 
@@ -859,9 +857,7 @@ for _, strategy in helpers.each_strategy() do
       end)
 
 
-      pending("log plugins sees same request in error_page handler (HTTP 494)", function()
-        -- PENDING: waiting on Nginx error_patch_preserve_method patch
-
+      it("log plugins sees same request in error_page handler (HTTP 494)", function()
         -- triggers error_page directive
         local uuid = utils.uuid()
 
@@ -893,9 +889,9 @@ for _, strategy in helpers.each_strategy() do
         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("", log_message.upstream_uri) -- no URI here since Nginx could not parse request
         assert.equal(uuid, log_message.request.headers["x-uuid"])
-        assert.equal("unavailable", log_message.request.headers.host)
+        assert.is_nil(log_message.request.headers.host) -- none as well
       end)
 
 
@@ -929,9 +925,7 @@ for _, strategy in helpers.each_strategy() do
       end)
 
 
-      pending("log plugins sees same request in error_page handler (HTTP 414)", function()
-        -- PENDING: waiting on Nginx error_patch_preserve_method patch
-
+      it("log plugins sees same request in error_page handler (HTTP 414)", function()
         -- triggers error_page directive
         local uuid = utils.uuid()
 
@@ -960,8 +954,6 @@ for _, strategy in helpers.each_strategy() do
 
         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

spec/helpers.lua

@@ -112,6 +112,7 @@ local conf = assert(conf_loader(TEST_CONF_PATH))
 
 _G.kong = kong_global.new()
 kong_global.init_pdk(_G.kong, conf, nil) -- nil: latest PDK
+kong_global.set_phase(kong, kong_global.phases.access)
 
 local db = assert(DB.new(conf))
 assert(db:init_connector())