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

…errors

This commit fixes the outstanding caveat of using logging plugins to log
NGINX-produced errors. The caveat - described in e709c95 - causes some
request properties (i.e. method and uri args) to be incorrectly logged.

Since e709c95, Kong executes plugins on NGINX-produced errors. However,
as described in the mentioned commit's message, a caveat with the
approach (note: the sanest one) is that the request method is overridden
by the `error_page` directive during the internal redirect (and the uri
args do not survive the redirect either).

This commit chooses to rely on the PDK to fix this limitation, and
manually parses the request headers when necessary (and possible).

Fix #4025
Fix #4751

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