Continued oddities using the PDK, plugin field setting didn't persist across phases?

[jeremyjpj0916]

Summary

Similar issues last time may have some relation: #5853

I won't paste the full plugin code here so we can just narrow in on the discussion of what I see as a current issue. TLDR we have a tx debugger plugin internally that prints all request/response headers and bodies to stdout and it seems the pdk still has some bugs from newer iterations. Take this code:

function KongTxDebugger:access(conf)
  if conf.log_request_body then
    kong.ctx.plugin.request_body = kong.request.get_raw_body()
  end
  
  if conf.log_response_body then
    kong.ctx.plugin.response_body = ""
  end
end

function KongTxDebugger:body_filter(conf)
  if conf.log_response_body and conf.max_response_body_size > 0 then
   local chunk = ngx.arg[1]
   local res_body = kong.ctx.plugin.response_body .. (chunk or "")
   kong.ctx.plugin.response_body = string.sub(res_body, 0, conf.max_response_body_size)
  end
end

The above will allow the access phase to initialize the kong.ctx.plugin.response_body to an empty string right? Yet behavior is that by the time the body_filter() phase executes, this kong.ctx.plugin.response_body is once again nil(rather than the empty string that access phase set it to) and causes me a stacktrace 💔 .

Stack trace in my testing of the plugin, this code used to work fine(sry don't know what Kong version this plugin used to fully work on because we only use it on demand) too so I don't think its the code but can copy full plugin handler/schema if yall want to play with it. Here is stacktrace(line 29 == local res_body = kong.ctx.plugin.response_body .. (chunk or "") ):

2020/08/05 22:29:27 [error] 14664#0: *2174338 failed to run body_filter_by_lua*: .../share/lua/5.1/kong/plugins/kong-tx-debugger/handler.lua:29: attempt to concatenate field 'response_body' (a nil value)
--
  | stack traceback:
  | .../share/lua/5.1/kong/plugins/kong-tx-debugger/handler.lua:29: in function <.../share/lua/5.1/kong/plugins/kong-tx-debugger/handler.lua:26>
  | /usr/local/kong/luarocks/share/lua/5.1/kong/init.lua:240: in function 'execute_plugins_iterator'
  | /usr/local/kong/luarocks/share/lua/5.1/kong/init.lua:1076: in function 'body_filter'
  | body_filter_by_lua:2: in main chunk, client: 10.96.138.104, server: kong, request: "GET /api/jeremy/test/v1 HTTP/1.1", host: "gateway-dev-core-dc2.company.com"
  | 2020/08/05 22:29:27 [error] 14664#0: *2174338 failed to run body_filter_by_lua*: .../share/lua/5.1/kong/plugins/kong-tx-debugger/handler.lua:29: attempt to concatenate field 'response_body' (a nil value)
  | stack traceback:
  | .../share/lua/5.1/kong/plugins/kong-tx-debugger/handler.lua:29: in function <.../share/lua/5.1/kong/plugins/kong-tx-debugger/handler.lua:26>
  | /usr/local/kong/luarocks/share/lua/5.1/kong/init.lua:240: in function 'execute_plugins_iterator'
  | /usr/local/kong/luarocks/share/lua/5.1/kong/init.lua:1076: in function 'body_filter'
  | body_filter_by_lua:2: in main chunk, client: 10.96.138.104, server: kong, request: "GET /api/jeremy/test/v1 HTTP/1.1", host: "gateway-dev-core-dc2.company.com"

cc @thibaultcha I know you looked at this stuff earlier with pdk complications and may have the relevant insights to it.

Steps To Reproduce

1. Try that plugin code in a vacuum and watch the nil pointer.

Additional Details & Logs

• Kong version 2.1.0 or 2.0.5 as well

[thibaultcha]

@jeremyjpj0916 Are you sure that the access phase was executed when requests produce this stacktrace?

[jeremyjpj0916]

Good shout, another plugin could decide to respond in its own access phase(if executes before this plugin in priority) which would prevent this specific plugins access phase from executing at all. Let me look into this scenario more tonight and will get back here.

[jeremyjpj0916]

Ahh, yep oauth2 was stopping it early so this ones access phase wasn't getting hit. Adjusted the priority on my logging pluggin so its access phase can be hit first and did some general cleanup. Sorry for the false alarm!

Its important to be aware of how other plugins can impact the execution of others for sure I just was thinking with too narrow a scope in this specific plugins code.