Merge pull request #1 from rainest/feat/body-log

Body logging

Author: rainest

README.md

@@ -1,10 +1,12 @@
 # kong-plugin-filter-log
 
 This plugin is similar to the standard Kong HTTP Log plugin, but with the
-ability to filter request and response header values.
+ability to filter request and response values.
+
+## Header filtering
 
 Two new configuration options, `response_header_filters` and 
-`request_header_filters`, are present. These are maps that accept header
+`request_header_filters`, add header-filtering capabilities. These are maps that accept header
 name+filter regular expression pairs. For example:
 
 ```
@@ -79,3 +81,20 @@ replaced with `XX REDACTED XX`:
 ```
 {"latencies":{"request":218,"kong":43,"proxy":175},"service":{"host":"httpbin.org","created_at":1545243827,"connect_timeout":60000,"id":"537a12a9-3fcd-4a17-a09d-726eb86e860b","protocol":"http","name":"httpbin","read_timeout":60000,"port":80,"path":"\/","updated_at":1545243827,"retries":5,"write_timeout":60000},"request":{"querystring":{"X-Example-Response":"whatever"},"size":"307","uri":"\/logme\/response-headers?X-Example-Response=whatever","url":"http:\/\/localhost:8000\/logme\/response-headers?X-Example-Response=whatever","headers":{"host":"localhost:8000","x-example-request":"this is somXX REDACTED XXgnore it","accept-encoding":"gzip, deflate","user-agent":"HTTPie\/1.0.2","accept":"*\/*","x-example-other-request":"send mail to XX REDACTED XX please","connection":"keep-alive"},"method":"GET"},"client_ip":"10.0.2.2","api":{},"upstream_uri":"\/response-headers?X-Example-Response=whatever","response":{"headers":{"content-type":"application\/json","date":"Sat, 26 Jan 2019 01:14:17 GMT","connection":"close","access-control-allow-credentials":"true","content-length":"106","x-kong-proxy-latency":"42","server":"gunicorn\/19.9.0","x-kong-upstream-latency":"175","via":"kong\/0.34-1-enterprise-edition","access-control-allow-origin":"*","x-example-response":"XX REDACTED XXXX REDACTED XX"},"status":200,"size":"459"},"route":{"created_at":1545938532,"strip_path":true,"hosts":[],"preserve_host":false,"regex_priority":0,"updated_at":1545938532,"paths":["\/logme"],"service":{"id":"537a12a9-3fcd-4a17-a09d-726eb86e860b"},"methods":[],"protocols":["http","https"],"id":"58d48d2a-acf3-40f6-866b-1376a8e79934"},"started_at":1548465257244}
 ```
+
+## Body filtering
+
+These plugins add the ability to log the request body and apply filters similar to the above. `body_filters` is an array of regular expression strings, which replace any matching content in the logged body with `XX REDACTED XX`.
+
+There are several tuning options to control how and when the body is logged:
+
+* `log_body` defaults to `false`, which will disable body logging altogether. Setting it to `true` will enable body logging.
+* `read_full_body` defaults to `false`, which will not attempt to read bodies larger than `client_body_buffer_size` at all. Setting it to `true` will read all request bodies, including those that have been buffered to disk.
+* `truncate_body` defaults to `true`, and truncates the body at either `body_size_limit` or `client_body_buffer_size` from kong.conf.
+* `body_size_limit` sets the size (in bytes) of body data that will be logged.
+
+It is *highly* recommended that `read_full_body` is always set to `false`. When set to `true`, reading larger files requires reading from disk, which has serious performance implications within Lua code. Users can expect an order of magnitude increase in latency if this is enabled. It should ideally only be used temporarily with a very specific set of matching criteria (e.g. only for a single route/consumer combo).
+
+If it is necessary to log larger bodies consistently, increasing `client_body_buffer_size` is preferable: it will lead to increased RAM usage, but does not incur disk read performance hits.
+
+Note that `truncate_body` and `body_size_limit` do not have a meaningful effect on the performance hit incurred by disk reads. They do have some impact on redaction performance after, but the time needed for that is typically much smaller than disk read time. In general, their main usage is to limit the amount of data sent to a logging service.

kong-plugin-filter-log-0.1.0-1.rockspec

@@ -1,10 +1,10 @@
 package = "kong-plugin-filter-log"
-version = "0.1.0-1"
+version = "0.1.1-1"
 
 supported_platforms = {"linux", "macosx"}
 source = {
   url = "git+https://github.com/rainest/kong-plugin-filter-log.git",
-  tag = "0.1.0"
+  tag = "0.1.1"
 }
 
 description = {

kong/plugins/file-log-filtered/handler.lua

@@ -3,6 +3,7 @@ local ffi = require "ffi"
 local cjson = require "cjson"
 local system_constants = require "lua_system_constants"
 local filtered_serializer = require "kong.plugins.log-serializers.filtered"
+local singletons =  require "kong.singletons"
 local BasePlugin = require "kong.plugins.base_plugin"
 
 local ngx_timer = ngx.timer.at
@@ -21,6 +22,40 @@ ffi.cdef[[
 int write(int fd, const void * ptr, int numbytes);
 ]]
 
+-- Convert NGINX-style byte notation to raw byte count
+-- @param `bytestring` NGINX-style bytestring
+local function calculate_bytes(bytestring)
+  local conversions = {k = 2^10, m = 2^20, g = 2^30}
+  local suffix = string.sub(bytestring, -1)
+  local count = tonumber(string.sub(bytestring, 1, -2))
+  return count * conversions[suffix]
+end
+
+-- Make the request body always available for later
+-- @param `conf` plugin configuration table
+local function access(conf)
+  local body
+
+  local limit = conf.body_size_limit or calculate_bytes(singletons.configuration.client_body_buffer_size)
+
+  if conf.log_body then
+    ngx.req.read_body()
+    body = ngx.req.get_body_data()
+    local body_filepath = ngx.req.get_body_file()
+    if not body and body_filepath and conf.read_full_body then
+      local file = io.open(body_filepath, "rb")
+      if conf.truncate_body then
+        body = file:read(limit)
+      else
+        body = file:read("*all")
+      end
+      file:close()
+    end
+  end
+
+  ngx.ctx.request_body = body
+end
+
 -- fd tracking utility functions
 local file_descriptors = {}
 
@@ -67,6 +102,11 @@ function FileLogFilteredHandler:new()
   FileLogFilteredHandler.super.new(self, "file-log")
 end
 
+function FileLogFilteredHandler:access(conf)
+  FileLogFilteredHandler.super.access(self)
+  access(conf)
+end
+
 function FileLogFilteredHandler:log(conf)
   FileLogFilteredHandler.super.log(self)
   local message = filtered_serializer.serialize(ngx, conf)

kong/plugins/file-log-filtered/schema.lua

@@ -24,6 +24,11 @@ return {
         keys = { type = "string" },
         values = { type = "string" }
     },
+    body_filters = { type = "array", elements = { type = "string" } },
+    log_body = { type = "boolean", default = false },
+    truncate_body = { type = "boolean", default = true },
+    read_full_body = { type = "boolean", default = false },
+    body_size_limit = { type = "number" },
     reopen = { type = "boolean", default = false },
   }
 }

kong/plugins/http-log-filtered/handler.lua

@@ -1,4 +1,5 @@
 local filtered_serializer = require "kong.plugins.log-serializers.filtered"
+local singletons =  require "kong.singletons"
 local BasePlugin = require "kong.plugins.base_plugin"
 local cjson = require "cjson"
 local url = require "socket.url"
@@ -60,6 +61,40 @@ local function parse_url(host_url)
   return parsed_url
 end
 
+-- Convert NGINX-style byte notation to raw byte count
+-- @param `bytestring` NGINX-style bytestring
+local function calculate_bytes(bytestring)
+  local conversions = {k = 2^10, m = 2^20, g = 2^30}
+  local suffix = string.sub(bytestring, -1)
+  local count = tonumber(string.sub(bytestring, 1, -2))
+  return count * conversions[suffix]
+end
+
+-- Make the request body always available for later
+-- @param `conf` plugin configuration table
+local function access(conf)
+  local body
+
+  local limit = conf.body_size_limit or calculate_bytes(singletons.configuration.client_body_buffer_size)
+
+  if conf.log_body then
+    ngx.req.read_body()
+    body = ngx.req.get_body_data()
+    local body_filepath = ngx.req.get_body_file()
+    if not body and body_filepath and conf.read_full_body then
+      local file = io.open(body_filepath, "rb")
+      if conf.truncate_body then
+        body = file:read(limit)
+      else
+        body = file:read("*all")
+      end
+      file:close()
+    end
+  end
+
+  ngx.ctx.request_body = body
+end
+
 -- Log to a Http end point.
 -- This basically is structured as a timer callback.
 -- @param `premature` see openresty ngx.timer.at function
@@ -118,6 +153,11 @@ function HttpLogFilteredHandler:serialize(ngx, conf)
   return cjson_encode(filtered_serializer.serialize(ngx, conf))
 end
 
+function HttpLogFilteredHandler:access(conf)
+  HttpLogFilteredHandler.super.access(self)
+  access(conf)
+end
+
 function HttpLogFilteredHandler:log(conf)
   HttpLogFilteredHandler.super.log(self)
 

kong/plugins/http-log-filtered/schema.lua

@@ -1,13 +1,3 @@
-local function check_for_value(value)
-  for i, entry in ipairs(value) do
-    local ok = find(entry, ":")
-    if not ok then
-      return false, "key '" .. entry .. "' has no value"
-    end
-  end
-  return true
-end
-
 return {
   fields = {
     http_endpoint = { required = true, type = "url" },
@@ -22,6 +12,11 @@ return {
         keys = { type = "string" },
         values = { type = "string" }
     },
+    body_filters = { type = "array", elements = { type = "string" } },
+    log_body = { type = "boolean", default = false },
+    truncate_body = { type = "boolean", default = true },
+    read_full_body = { type = "boolean", default = false },
+    body_size_limit = { type = "number" },
     keepalive = { default = 60000, type = "number" }
   }
 }

kong/plugins/log-serializers/filtered.lua

@@ -6,16 +6,40 @@ local EMPTY = tablex.readonly({})
 
 local function filter_headers(headers, filter_pairs)
   if filter_pairs then
+    local n
+    local err
     for header, regex in pairs(filter_pairs) do
       if headers[header] then
-        headers[string.lower(header)] = ngx.re.gsub(headers[header], regex, "XX REDACTED XX")
+        headers[string.lower(header)], n, err = ngx.re.gsub(headers[header], regex, "XX REDACTED XX")
+        if err then
+          ngx.log(ngx.ERR, header, " redaction regex \"", regex, "\" failed: ", err)
+          headers[string.lower(header)] = ""
+        end
       end
     end
   end
 
   return headers
 end
 
+local function filter_body(filters)
+  local body = ngx.ctx.request_body or ""
+  if filters and body ~= "" then
+    local n
+    local err
+    for i, regex in pairs(filters) do
+      body, n, err = ngx.re.gsub(body, regex, "XX REDACTED XX")
+      if err then
+        -- regex application failed, which may leave sensitive data unredacted
+        -- best to simply discard everything
+        ngx.log(ngx.ERR, "body redaction regex \"", regex, "\" failed: ", err)
+        return ""
+      end
+    end
+  end
+  return body
+end
+
 function _M.serialize(ngx, conf)
   local authenticated_entity
   if ngx.ctx.authenticated_credential ~= nil then
@@ -26,6 +50,7 @@ function _M.serialize(ngx, conf)
   end
 
   local request_uri = ngx.var.request_uri or ""
+  local body = filter_body(conf.body_filters)
 
   return {
     request = {
@@ -34,7 +59,8 @@ function _M.serialize(ngx, conf)
       querystring = ngx.req.get_uri_args(), -- parameters, as a table
       method = ngx.req.get_method(), -- http method
       headers = filter_headers(ngx.req.get_headers(), conf.request_header_filters),
-      size = ngx.var.request_length
+      size = ngx.var.request_length,
+      body = body
     },
     upstream_uri = ngx.var.upstream_uri,
     response = {