search

Kong / kong-python-pdk

Write Kong plugins in Python (Experimental)
Apache License 2.0
40 stars 14 forks source link

Possibly malformed event payload #136

Open basilnsage opened 8 months ago

basilnsage commented 8 months ago

Hiya,

I'm running into a sporadic issue with a custom Python plugin. Occasionally, it looks like the plugin server receives a malformed event to handle.

Kong Gateway: 3.3.0 Python-pdk: 0.36 Kong Ingress Controller: 2.10 Proxy env vars:

...
KONG_PLUGINS : bundled,my-plugin
KONG_PLUGINSERVER_MY_PLUGIN_QUERY_CMD : /home/kong/plugins/python/my_plugin.py -p /kong-prefix/ -d
KONG_PLUGINSERVER_MY_PLUGIN_SOCKET : /kong-prefix/my-plugin.sock
KONG_PLUGINSERVER_MY_PLUGIN_START_CMD : /home/kong/plugins/python/my_plugin.py -p /kong-prefix/ --no-lua-style -g
KONG_PREFIX : /kong-prefix/
...

Logs:

2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377] INFO - [02:08:35] instance #1259 of my-plugin started, context: ngx.timer
2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377] INFO - [02:08:35] instance #1260 of my-plugin started, context: ngx.timer
2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377] ERROR - [02:08:35] rpc: #6285 exception: Traceback (most recent call last):, context: ngx.timer
2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377]   File "/usr/local/lib/python3.10/dist-packages/kong_pdk/listener.py", line 68, in handle, context: ngx.timer
2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377]     ret = getattr(self.ps, cmd_r)(*args), context: ngx.timer
2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377]   File "/usr/local/lib/python3.10/dist-packages/kong_pdk/server.py", line 54, in wrapper, context: ngx.timer
2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377]     raise ex, context: ngx.timer
2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377]   File "/usr/local/lib/python3.10/dist-packages/kong_pdk/server.py", line 51, in wrapper, context: ngx.timer
2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377]     r = fn(*args, **kwargs), context: ngx.timer
2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377]   File "/usr/local/lib/python3.10/dist-packages/kong_pdk/server.py", line 278, in handle_event, context: ngx.timer
2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377]     iid = event['InstanceId'], context: ngx.timer
2023/10/26 18:08:35 [info] 2375#0: *311 [my-plugin:2377] KeyError: 'InstanceId', context: ngx.timer
2023/10/26 18:08:35 [error] 2375#0: *188104 [kong] mp_rpc.lua:354 [my-plugin] 'InstanceId', client: 10.0.131.51, server: kong, request: "GET /foo HTTP/1.1", host: "bar"

The KeyError: 'InstanceId' makes me think that the error is from https://github.com/Kong/kong-python-pdk/blob/master/kong_pdk/server.py#L278, and that the event argument is sometimes malformed.

Any ideas? Please and thank you!

basilnsage commented 8 months ago

To help me poke around with this some more, I enabled debug logging on my proxy deployment. I had to manually untangle logs, but I believe these are good representations of logs from successful an unsuccessful requests. HTTP headers have been redacted for security and legibility reasons.

Debug logs for a successful request:

2023/10/27 18:08:35 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:35] rpc: #1308 method: plugin.StartInstance args: [{'Config': '{""__plugin_id"":""460fa285-95a8-413a-88a3-30f4aded0f78"",""__key__"":""plugins:my-plugin:::::e3edb0b8-44a4-48bc-83dc-310b8f731459"",""__seq__"":1,""configA"":""foo"",""configB"":""bar""}', 'Name': 'my-plugin'}], context: ngx.timer
2023/10/27 18:08:35 [info] 2375#0: *311 [my-plugin:2377] INFO - [02:08:35] instance #262 of my-plugin started, context: ngx.timer
2023/10/27 18:08:35 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:35] rpc: #1308 return: {'Name': 'my-plugin', 'Id': 262, 'Config': {'__plugin_id': '460fa285-95a8-413a-88a3-30f4aded0f78', '__key__': 'plugins:my-plugin:::::e3edb0b8-44a4-48bc-83dc-310b8f731459', '__seq__': 1, 'configA': 'foo', 'configB': 'bar'}, 'StartTime': 1698430115.841085}, context: ngx.timer
2023/10/27 18:08:35 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:35] rpc: #1311 method: plugin.HandleEvent args: [{'InstanceId': 262, 'EventName': 'rewrite'}], context: ngx.timer
2023/10/27 18:08:35 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:35] rpc: #1311 return: {'Data': {'Method': 'kong.request.get_headers', 'Args': ()}, 'EventId': 262}, context: ngx.timer
2023/10/27 18:08:35 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:35] rpc: #1313 method: plugin.StepMultiMap args: [{'Data': {...}, 'EventId': 262}], context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1313 return: {'Data': {'Method': 'kong.service.request.set_headers', 'Args': ({...})}, 'EventId': 262}, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1314 method: plugin.CloseInstance args: [262], context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1314 return: {'Name': 'my-plugin', 'Id': 262, 'Config': {'__plugin_id': '460fa285-95a8-413a-88a3-30f4aded0f78', '__key__': 'plugins:my-plugin:::::e3edb0b8-44a4-48bc-83dc-310b8f731459', '__seq__': 1, 'configA': 'foo', 'configB': 'bar'}}, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1316 method: plugin.Step args: [{'EventId': 262}], context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1316 return: {'Data': 'ret', 'EventId': 262}, context: ngx.timer

For an unsuccessful request:

2023/10/27 18:08:35 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:35] rpc: #1312 method: plugin.StartInstance args: [{'Config': '{""__plugin_id"":""460fa285-95a8-413a-88a3-30f4aded0f78"",""__key__"":""plugins:my-plugin:::::e3edb0b8-44a4-48bc-83dc-310b8f731459"",""__seq__"":1,""configA"":""foo"",""configB"":""bar""}', 'Name': 'my-plugin'}], context: ngx.timer
2023/10/27 18:08:35 [info] 2375#0: *311 [my-plugin:2377] INFO - [02:08:35] instance #263 of my-plugin started, context: ngx.timer
2023/10/27 18:08:35 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:35] rpc: #1312 return: {'Name': 'my-plugin', 'Id': 263, 'Config': {'__plugin_id': '460fa285-95a8-413a-88a3-30f4aded0f78', '__key__': 'plugins:my-plugin:::::e3edb0b8-44a4-48bc-83dc-310b8f731459', '__seq__': 1, 'configA': 'foo', 'configB': 'bar'}, 'StartTime': 1698430115.9224753}, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1317 method: plugin.HandleEvent args: [{'EventName': 'rewrite'}], context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] ERROR - [02:08:36] rpc: #1317 exception: Traceback (most recent call last):, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] File ""/usr/local/lib/python3.10/dist-packages/kong_pdk/listener.py"", line 68, in handle, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] ret = getattr(self.ps, cmd_r)(*args), context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] File ""/usr/local/lib/python3.10/dist-packages/kong_pdk/server.py"", line 54, in wrapper, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] raise ex, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] File ""/usr/local/lib/python3.10/dist-packages/kong_pdk/server.py"", line 51, in wrapper, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] r = fn(*args, **kwargs), context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] File ""/usr/local/lib/python3.10/dist-packages/kong_pdk/server.py"", line 278, in handle_event, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] iid = event['InstanceId'], context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] KeyError: 'InstanceId', context: ngx.timer
2023/10/27 18:08:36 [error] 2375#0: *20177 [kong] mp_rpc.lua:354 [my-plugin] 'InstanceId', client: 10.0.150.241, server: kong, request: ""GET /weh HTTP/1.1"", host: ""baz""
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1318 method: plugin.CloseInstance args: [263], context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1318 return: {'Name': 'my-plugin', 'Id': 263, 'Config': {'__plugin_id': '460fa285-95a8-413a-88a3-30f4aded0f78', '__key__': 'plugins:my-plugin:::::e3edb0b8-44a4-48bc-83dc-310b8f731459', '__seq__': 1, 'configA': 'foo', 'configB': 'bar'}}, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1319 return: {'Data': {'Method': 'kong.request.get_headers', 'Args': ()}, 'EventId': 263}, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1320 method: plugin.StepMultiMap args: [{'Data': {...}, 'EventId': 263}], context: ngx.timer
10.0.150.241 - - [27/Oct/2023:18:08:36 +0000] ""GET /weh HTTP/1.1"" 500 75 ""-"" ""user agent""
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1320 return: {'Data': {'Method': 'kong.service.request.set_headers', 'Args': ({...})}, 'EventId': 263}, context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1322 method: plugin.Step args: [{'EventId': 263}], context: ngx.timer
2023/10/27 18:08:36 [info] 2375#0: *311 [my-plugin:2377] DEBG - [02:08:36] rpc: #1322 return: {'Data': 'ret', 'EventId': 263}, context: ngx.timer

Edit: I've additionally noticed that the error usually coincides with sudden bursts of requests. It makes me wonder if there's some concurrency bug that causes the instance ID to come back as nil. That would remove the InstanceId key from the table (I think) and would track with the stacktrace in the logs.

nowNick commented 8 months ago

Thank you @basilnsage for this thorough investigation! I'll take a look at it and try to help the best way I can