Enhanced HTTP logging idea

[jeremyjpj0916]

Two things I would like:

When a tx occurs, if Kong is the one rejecting it (invalid creds/user not authorized) etc. and is including that as its message: “kong error here” json response, a way to capture that Kong generated error message body and log the short string in my http log plugin. These guys are the errors Kong throws I am talking about:

Other thing I want to log are the nginx errors on proxying for a given tx, specifically the l4 errors around upstream timeouts, upstream prematurely closed connection while reading response headers, all manner of upstream errors when Kong and the backend are trying to talk . I currently log things like l4 errors to the docker stdout so I see the l4/nginx errors in terminal(This is not effective, especially under load and lots of errors, terminal is way too chatty to follow coherently), but does OpenResty or Kong’s PDK expose what I am looking for here as some sort of getter ngx.{error_msg_variable}? :

--Include this one in my http log plugin(with some of the extraneous message fat trimmed off probably)
2018/11/18 14:32:38 [error] 33#0: *11974109 upstream timed out (110: Operation timed out) while reading response header from upstream, client: ip_here, server: kong, request: "POST /api/backend/service/servicename/v1.0 HTTP/1.1", upstream: "https://ip_here:port/api/backend/service/servicename/v1.0", host: "gateway.company.com"

--Ignore this one in my http log plugin(it is my http log plugin throwing an error in this example though :)   )
2018/11/18 14:42:05 [error] 32#0: *11983636 [lua] sender.lua:76: send(): failed request to splunk.company.com:443: closed, context: ngx.timer, client: ip_here, server: 0.0.0.0:8443

Gonna try to add the additional info to my plugin here: https://github.com/Optum/kong-splunk-log, and maybe to Kong’s own basic.lua log serializer if they would want that as a PR after I test it out on my own.

https://github.com/openresty/lua-resty-core/blob/master/lib/ngx/errlog.md I saw this which may help grabbing these l4 errors, but was hoping I could get away without having to modify Kong to support this desired logic.

Thanks,
Jeremy

[thibaultcha]

Hi,

Both features would require you to modify Kong, as you probably guessed. The former could be done with a custom log serializer (something that we still aim at providing as an option, out of the box), but for now would require you to either edit the default serializer bundled with Kong, or to make your own and replace the default one with yours in the plugin’s code. In that serializer you could then catch those Kong-produced status codes.

The second one is harder. You can “catch” Nginx-produced error logs out of the box by configuring the error_log directive to send logs to syslog (instead of files), but that is it. The OpenResty API you pointed to allows for catching these logs in Lua, but no work has been done in Kong to integrate it (and none is planned so far, at least on the short/mid term), as it is quite low on our priority list… It does what you are asking though, so you could make this feature request into a plugin maybe?

[jeremyjpj0916]

Thanks, I feared there was no easy way hah. I will see what I can cook up though.

[jeremyjpj0916]

I actually whipped up some code today testing it. Printing via ngx.log() yeilded me the data I wanted, but when I try to actually reference the error message in the other plugin it seems to be nil, i tried using the pdk and even the ngx.ctx directly and neither seemed to work, this could be neat to release into the wild once it works :

Custom Kong Template additions:

# enable capturing error logs
lua_capture_error_log 5m;

  init_by_lua_block {
      Kong = require 'kong'
      Kong.init()
      local errlog = require "ngx.errlog"
      local status1, err1 = errlog.set_filter_level(ngx.ERR)
      if not status1 then
        ngx.log(ngx.ERR, err1)
      end
}

handler.lua

local BasePlugin = require "kong.plugins.base_plugin"
local KongErrorLog = BasePlugin:extend()
local errlog = require "ngx.errlog"

KongErrorLog.PRIORITY = 3
KongErrorLog.VERSION = "0.1.0"

-- Only provide `name` when deriving from this class. Not when initializing an instance.
function KongErrorLog:new(name)
  name = name or "kong-error-log"
  KongErrorLog.super.new(self, name)
  self.ngx_log = ngx.log
  self.name = name
end

function KongErrorLog:log(conf)
  KongErrorLog.super.log(self)
  --Get all err messages from global buffer during the tx, get_logs() clears them from the buffer upon success.
  local res, err = errlog.get_logs()
  
  if not res then
    ngx.log(ngx.ERR, err)
  end
  
  if res then
    for i = 1, #res, 3 do
        local msg  = res[i + 2] -- res[i + 2] gives us the data of the error.
        if string.find(msg, conf.keyword) then --Pattern match on schema set related errors
          msg = msg:gsub('"','') --Strip double quotes from string so its safe for logging to json
          kong.ctx.shared.errmsg = msg --Set it as a shared context for other plugins to utilize
          --ngx.ctx.errmsg = msg --Set it as a shared context for other plugins to utilize
          --ngx.log(ngx.NOTICE, "TEST MESSAGE " .. ngx.ctx.errmsg)
          break
        end
    end
  end
end

return KongErrorLog

Then I try to reference that same variable here:

Optum/kong-splunk-log/blob/master/src/basic.lua#L30

Any ideas why it would lose its value or a possible fix?

Also overall not crazy excited about the design currently, there is a chance I think where the logs of other services could get added to the wrong Splunk tx log if concurrent errors occur at the same time currently which will need some thinking. But hey this is a rough start at how we can get those ngx error logs luafied and externalized!

-Jeremy

[jeremyjpj0916]

I AM DUMB, ignore me, I had priorities swapped on new plugin vs when splunk runs. Need to run error log plugin before splunk!

EDIT AGAIN - Nope, never mind even priority 13 on the error log plugin I just wrote vs 12 on the splunk log did not fix it.

EDIT EDIT - I am so badddd. I had disabled my error log plugin and thats why it didnt workkkkk(most recently) . All is well now

Well this is looking nice, I am happy with the output and can now see the ngx error in my log!

I will be open sourcing this plugin soon enough and will build some documentation around it for the Kong Hub . Its not crazy flexible but it will be really good for team that wants to capture errors and by default capturing errors surrounding upstream connections then this will help.

-Jeremy

Edit -

I think I am understanding some of Core Kong a bit better. @thibaultcha , rather than filling up code in the Kong custom template for doing things in the init_by_lua_block, I can simply put it directly in one of my plugins :init_worker() function since the Kong.init() has a nice for loop executing the init_worker() call for every plugin found, this is beneficial to other Kongers because then they won’t have to necessarily run a custom template just to leverage this plugin I am cooking up(well they will need to add lua_capture_error_log 5m; with the other shms because I suppose that can’t be done inside the lua plugin code itself). I think this is also applicable when you suggested initializing a separate mlcache for my oidc cache values to declare such a cache in the :init_worker() phase of the plugin itself similar to how you initialize the kong singletons cache in the Kong.init() itself.

[thibaultcha]

since the Kong.init() has a nice for loop executing the init_worker() call for every plugin

Where did you see such a loop in the init context? The init_worker plugins loop should be executed within the init_worker phase.

A way to execute code in the init phase is to place it at the top-level chunk of your module (which also makes it execute within the require call that loads said plugin’s module, so beware for it could have some other limitations in particular related to resumability of the Lua VM upon I/O calls). Executing Lua code in the init phase has the nice benefit that you can leverage the CoW feature of modern operating systems.

need to add lua_capture_error_log 5m; with the other shms because I suppose that can’t be done inside the lua plugin code itself

In Kong 0.14+, you can inject those via an injected nginx directive, e.g.:

export KONG_NGINX_HTTP_LUA_SHARED_DICT=lua_capture_error_log 5m

See this loop for implementation details.

[jeremyjpj0916]

Does not seem to be any difference in functional in testing from letting the plugin logic implement it in the init_worker phase vs the init_by_lua_block in a custom nginx conf directly just from high level testing for the error log feature openresty has or for things like declaring an mlcache unless I am missing something. From reading the description:

openresty/lua-nginx-module

 this hook will just run after init_by_lua*.

So no real harm done?

[thibaultcha]

No harm in initializing this in init_worker, no.