Kong Websockets Logger Plugin

Questions
1

Welp as the name states I been thinking about taking a crack at logging with a web-socket connection using this lib: https://github.com/openresty/lua-resty-websocket, my plugin ended up being a morph of the http logger(to format the data) and websocket logic:

schema.lua

return {
  fields = {
    websocket_connect = { required = true,  default = "wss://<host>:<port>/<path>", type="string"}
  }
}

handler.lua

local basic_serializer = require "kong.plugins.kong-websocket-log.basic"
local BasePlugin = require "kong.plugins.base_plugin"
local cjson = require "cjson"
local client = require "resty.websocket.client"
local string_format = string.format
local cjson_encode = cjson.encode
local KongWebSocketLog = BasePlugin:extend()

KongWebSocketLog.PRIORITY = 12
KongWebSocketLog.VERSION = "0.1.0"

local function log(premature, conf, body, name)
  if premature then
    return
  end
  name = "[" .. name .. "] "
  
  if kong.ctx.plugin.wb_status == nil then
    local kong.ctx.plugin.wb, err = client:new()
    local ok, err = kong.ctx.plugin.wb:connect(conf.websocket_connect)
      if not ok then
        ngx.log(ngx.ERR, name .. "failed to connect: " .. err)
        kong.ctx.plugin.wb_status = nil
        return
      else
        kong.ctx.plugin.wb_status = "success"
      end
  end
  
  --Already have active websocket connection
  if kong.ctx.plugin.wb_status == "success" then
    local bytes, err = kong.ctx.plugin.wb:send_text(data)
    if not bytes then
        ngx.log(ngx.ERR, name .. "failed to send frame: ", err)
        kong.ctx.plugin.wb_status = nil
        return
    end
  end
end

function KongWebSocketLog:new(name)
  KongWebSocketLog.super.new(self, name or "kong-websocket-log")
end

function KongWebSocketLog:serialize(ngx, conf)
  return cjson_encode(basic_serializer.serialize(ngx))
end

function KongWebSocketLog:log(conf)
  KongWebSocketLog.super.log(self)

  local ok, err = ngx.timer.at(0, log, conf, self:serialize(ngx, conf), self._name)
  if not ok then
    ngx.log(ngx.ERR, "[" .. self._name .. "] failed to create timer: ", err)
  end
end

return KongWebSocketLog

Basically my goal in mind is for the Kong node to share 1 active websocket connection for the plugin to utilize for high throughput of logging API transactions. Do we think this will work or need more tweaks? I will be testing it out probably over the next few days.

Other enhancements I may make: additional options, possible timeout configuration.

Once its working will open source in a repo and get it out there for the world :slight_smile: .

1 Like
2

Tested it a bit in this state now:

local basic_serializer = require "kong.plugins.kong-websocket-log.basic"
local BasePlugin = require "kong.plugins.base_plugin"
local cjson = require "cjson"
local client = require "resty.websocket.client"
local string_format = string.format
local cjson_encode = cjson.encode
local KongWebSocketLog = BasePlugin:extend()

KongWebSocketLog.PRIORITY = 12
KongWebSocketLog.VERSION = "0.1.0"

local function log(premature, conf, body, name)
  if premature then
    return
  end
  name = "[" .. name .. "] "
  
  if kong.ctx.plugin.wb_status == nil then
    local ok, err
    kong.ctx.plugin.wb, err = client:new()
    ok, err = kong.ctx.plugin.wb:connect(conf.websocket_connect)
      ngx.log(ngx.ERR, name .. "In websocket Connect logic!")
      if not ok then
        ngx.log(ngx.ERR, name .. "failed to connect: " .. err)
        kong.ctx.plugin.wb_status = nil
        return
      else
        kong.ctx.plugin.wb_status = "success"
      end
  end
  
  --Already have active websocket connection
  if kong.ctx.plugin.wb_status == "success" then
    local bytes, err = kong.ctx.plugin.wb:send_text(data)
    ngx.log(ngx.ERR, name .. "In websocket send data logic!")
    if not bytes then
        ngx.log(ngx.ERR, name .. "failed to send frame: ", err)
        kong.ctx.plugin.wb_status = nil
        return
    end
  end
end

function KongWebSocketLog:new(name)
  KongWebSocketLog.super.new(self, name or "kong-websocket-log")
end

function KongWebSocketLog:serialize(ngx, conf)
  return cjson_encode(basic_serializer.serialize(ngx))
end

function KongWebSocketLog:log(conf)
  KongWebSocketLog.super.log(self)

  local ok, err = ngx.timer.at(0, log, conf, self:serialize(ngx, conf), self._name)
  if not ok then
    ngx.log(ngx.ERR, "[" .. self._name .. "] failed to create timer: ", err)
  end
end

return KongWebSocketLog

Seeing a lot of this:

2018/09/28 21:58:35 [error] 38#0: *5239 [lua] handler.lua:22: [kong-websocket-log] In websocket Connect logic!, context: ngx.timer, client: 10.xxx.xx.x, server: 0.0.0.0:8443
2018/09/28 21:58:35 [error] 38#0: *5239 [lua] handler.lua:35: [kong-websocket-log] In websocket send data logic!, context: ngx.timer, client: 10.xxx.xx.x, server: 0.0.0.0:8443
2018/09/28 21:58:36 [error] 33#0: *5308 [lua] handler.lua:22: [kong-websocket-log] In websocket Connect logic!, context: ngx.timer, client: 10.xxx.xx.x, server: 0.0.0.0:8443
2018/09/28 21:58:36 [error] 33#0: *5308 [lua] handler.lua:35: [kong-websocket-log] In websocket send data logic!, context: ngx.timer, client: 10.xxx.xx.x, server: 0.0.0.0:8443
2018/09/28 21:58:39 [error] 33#0: *5406 [lua] handler.lua:22: [kong-websocket-log] In websocket Connect logic!, context: ngx.timer, client: 10.xxx.xx.x, server: 0.0.0.0:8443
2018/09/28 21:58:39 [error] 33#0: *5406 [lua] handler.lua:35: [kong-websocket-log] In websocket send data logic!, context: ngx.timer, client: 10.xxx.xx.x, server: 0.0.0.0:8443

Why in the world is the first if check constantly going inside :frowning: ? Should be connecting once then just sending data eh? On a positive note not seeing the failure messages if the connection failed or the data not sent :slight_smile: !

3

Hey Jeremy,

Nice to see your plugin to log websocket requests. I am trying to monitor or meter the traffic for websocket connection.
I am able to log the event, once client hits the request first time with status code as 200. When client closes the connection, then also I got the log event with status code as 101. I can compute the timestamp once I get the status code as 101 and compute the difference b/w that timestamp and started_at timestamp to get the time for which the client connection is in use.
But there is a scenario when multiple client connections are active then in that case, how the metering works. T
There could be a chance when web socket server only terminates and client connection was active.

Could you please help me to monitor or meter the traffic in case of websocket proxy requests?