Python Pluginserver unable to start

Questions
1

Hello, I am attempting to run a sample Python plugin in our kong proxy container, but am running into some issues when the pluginserver is starting. Based on other similar threads on this forum and in GitHub issues, I feel there might be some permissions-related issues.

We are using this docker file

# Based on https://docs.konghq.com/gateway/latest/plugin-development/pluginserver/plugins-kubernetes/
# However, the above doc assumes an alpine-based image, so the commands have been slightly modified
FROM kong:3.2 as kong-with-python-plugins

USER root
RUN apt-get update && \
    apt-get install -y python3 python3-pip && \
    pip3 install kong-pdk

COPY kong-pluginserver.py /opt/kong-python-plugins/kong-pluginserver.py
COPY plugins /opt/kong-python-plugins/plugins
RUN chown -R kong:kong /opt/kong-python-plugins
RUN chmod -R 777 /opt/kong-python-plugins

USER kong
ENTRYPOINT ["/docker-entrypoint.sh"]
EXPOSE 8000 8443 8001 8444
STOPSIGNAL SIGQUIT
HEALTHCHECK --interval=10s --timeout=10s --retries=10 CMD kong health
CMD ["kong", "docker-start"]

kong-pluginserver.py is this file verbatim: https://github.com/Kong/kong-python-pdk/blob/master/kong-pluginserver.py

The only file inside of plugins is a copy of the following file, although named to python_example.py and using a different name start_dedicated_server("python_example", Plugin, version, priority, Schema): https://github.com/Kong/kong-python-pdk/blob/master/examples/py-hello.py

I have set the following environment variables:

- name: KONG_PLUGINS
  value: "bundled,python_example"
- name: KONG_PLUGINSERVER_NAMES
  value: "py"
- name: KONG_PLUGINSERVER_PY_SOCKET
  value: "/usr/local/kong/python_pluginserver.sock"
- name: KONG_PLUGINSERVER_PY_START_CMD
  value: "/opt/kong-python-plugins/kong-pluginserver.py --plugins-directory /opt/kong-python-plugins/plugins"
- name: KONG_PLUGINSERVER_PY_QUERY_CMD
  value: "/opt/kong-python-plugins/kong-pluginserver.py --plugins-directory /opt/kong-python-plugins/plugins --dump-all-plugins"

When the proxy container starts, the following log messages are written:

2023/08/17 18:50:14 [warn] 1#0: the "user" directive makes sense only if the master process runs with super-user privileges, ignored in /usr/local/kong/nginx.conf:6
nginx: [warn] the "user" directive makes sense only if the master process runs with super-user privileges, ignored in /usr/local/kong/nginx.conf:6
2023/08/17 18:50:15 [notice] 1#0: using the "epoll" event method
2023/08/17 18:50:15 [notice] 1#0: openresty/1.21.4.1
2023/08/17 18:50:15 [notice] 1#0: OS: Linux 5.10.184-175.749.amzn2.x86_64
2023/08/17 18:50:15 [notice] 1#0: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2023/08/17 18:50:15 [notice] 1#0: start worker processes
2023/08/17 18:50:15 [notice] 1#0: start worker process 1202
2023/08/17 18:50:15 [notice] 1#0: start worker process 1203
2023/08/17 18:50:15 [notice] 1203#0: *2 [lua] globalpatches.lua:66: sleep(): executing a blocking 'sleep' (0.001 seconds), context: init_worker_by_lua*
2023/08/17 18:50:15 [notice] 1203#0: *2 [lua] globalpatches.lua:66: sleep(): executing a blocking 'sleep' (0.002 seconds), context: init_worker_by_lua*
2023/08/17 18:50:15 [notice] 1202#0: *1 [lua] init.lua:240: purge(): [DB cache] purging (local) cache, context: init_worker_by_lua*
2023/08/17 18:50:15 [notice] 1202#0: *1 [lua] init.lua:240: purge(): [DB cache] purging (local) cache, context: init_worker_by_lua*
2023/08/17 18:50:15 [notice] 1202#0: *1 [lua] init.lua:415: every(): [timer-ng] fallback to ngx.timer.every [interval = 86400], context: init_worker_by_lua*
2023/08/17 18:50:15 [notice] 1203#0: *2 [lua] init.lua:415: every(): [timer-ng] fallback to ngx.timer.every [interval = 86400], context: init_worker_by_lua*
2023/08/17 18:50:15 [notice] 1202#0: *178 [kong] process.lua:252 Starting py, context: ngx.timer
2023/08/17 18:50:15 [crit] 1203#0: *296 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/08/17 18:50:15 [crit] 1202#0: *298 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/08/17 18:50:15 [notice] 1202#0: signal 17 (SIGCHLD) received from 1204
2023/08/17 18:50:15 [notice] 1202#0: *178 [kong] process.lua:268 external pluginserver 'py' terminated: exit 1, context: ngx.timer
2023/08/17 18:50:15 [crit] 1202#0: *298 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/08/17 18:50:15 [crit] 1203#0: *296 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer

And then every so often, there is an attempt to restart the pluginserver:

2023/08/17 19:16:04 [notice] 1202#0: *298 [kong] process.lua:252 Starting py, context: ngx.timer
2023/08/17 19:16:04 [notice] 1202#0: signal 17 (SIGCHLD) received from 1212
2023/08/17 19:16:04 [notice] 1202#0: *298 [kong] process.lua:268 external pluginserver 'py' terminated: exit 1, context: ngx.timer

If I ssh into the container and manually run /opt/kong-python-plugins/kong-pluginserver.py --plugins-directory /opt/kong-python-plugins/plugins, I get the following output and I can confirm that the /usr/local/kong/python_pluginserver.sock socket gets created:

kong@proxy-kong-685499c77f-vr5lb:/$ /opt/kong-python-plugins/kong-pluginserver.py --plugins-directory /opt/kong-python-plugins/plugins
WARN - [02:51:11] lua-style return values are used, this will be deprecated in the future; instead of returning (data, err) tuple, only data will be returned and err will be thrown as PDKException; please adjust your plugin to use the new python-style PDK API.
INFO - [02:51:11] server started at path /usr/local/kong/python_pluginserver.sock

If I add print statements and/or commands to touch files at the beginning of the python script, I don’t see any outputs in logs or the files on the filesystem, but if I run the pluginserver command manually inside the container, the files do get created.

These observations lead me to believe that Nginx/OpenResty/Kong is unable to correctly start/invoke the pluginserver file.

Some permissions info in case it’s relevant:

kong@proxy-kong-86696bcdb5-glwx7:/usr/local/kong$ ls -al
total 240
drwxrwxr-x 1 kong root   4096 Aug 17 19:15 .
drwxr-xr-x 1 root root     18 Aug 16 16:01 ..
-rw-r--r-- 1 kong kong 208568 Aug 17 19:15 .ca_combined
-rw-r----- 1 kong kong   8026 Aug 17 19:15 .kong_env
drwx------ 2 kong kong      6 Aug 17 19:15 client_body_temp
drwx------ 2 kong kong     38 Aug 17 19:15 dbless.lmdb
drwx------ 2 kong kong      6 Aug 17 19:15 fastcgi_temp
drwxrwxr-x 6 kong root     68 Aug 16 16:01 include
drwxrwxr-x 3 kong root    107 Aug 16 16:01 lib
drwxr-xr-x 2 kong kong     89 Aug 17 19:15 logs
-rw-r--r-- 1 kong kong   2647 Aug 17 19:15 nginx-kong-stream.conf
-rw-r--r-- 1 kong kong  13789 Aug 17 19:15 nginx-kong.conf
-rw-r--r-- 1 kong kong    372 Aug 17 19:15 nginx.conf
drwxr-xr-x 2 kong kong     23 Aug 17 19:15 pids
drwx------ 2 kong kong      6 Aug 17 19:15 proxy_temp
drwx------ 2 kong kong      6 Aug 17 19:15 scgi_temp
drwxr-xr-x 2 kong kong    267 Aug 17 19:15 ssl
drwx------ 2 kong kong      6 Aug 17 19:15 uwsgi_temp
srw-rw-rw- 1 kong kong      0 Aug 17 19:15 worker_events.sock

kong@proxy-kong-86696bcdb5-glwx7:/opt/kong-python-plugins$ ls -al
total 4
drwxrwxrwx 1 kong kong 21 Aug 16 20:40 .
drwxr-xr-x 1 root root 33 Aug 16 20:37 ..
-rwxrwxrwx 1 kong kong 68 Aug 16 20:30 kong-pluginserver.py
drwxrwxrwx 1 kong kong 25 Aug 17 19:15 plugins

kong@proxy-kong-86696bcdb5-glwx7:/opt/kong-python-plugins/plugins$ ls -al
total 4
drwxrwxrwx 1 kong kong   25 Aug 17 19:15 .
drwxrwxrwx 1 kong kong   21 Aug 16 20:40 ..
drwxr-xr-x 2 kong kong   44 Aug 17 19:15 __pycache__
-rwxrwxrwx 1 kong kong 1164 Aug 16 20:40 python_example.py
2

The only related or partially-related similar threads I could find are:

Finally, I’ll add that nginx is being run as kong:

kong@proxy-kong-86696bcdb5-glwx7:/$ ps aux
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
kong         1  0.1  0.1 416500 60796 ?        Ss   19:15   0:00 nginx: master process /usr/local/openresty/nginx/sbin/nginx -p /usr/local/kong -c nginx.conf
kong      1202  0.2  0.3 598200 102788 ?       S    19:15   0:01 nginx: worker process
kong      1203  0.1  0.3 622032 127968 ?       S    19:15   0:00 nginx: worker process

Please let me know if I can provide more diagnostic info. Thank you!

3

After sleeping on it, I decided to increase the logging level, and discovered that when Kong/Nginx invokes the script, it must be using a different PYTHONPATH or Python config, since I saw the following error:

23/08/21 16:36:00 [notice] 1202#0: *216 [kong] process.lua:252 Starting py, context: ngx.timer
2023/08/21 16:36:00 [info] 1202#0: *216 [py:1225] Traceback (most recent call last):, context: ngx.timer
2023/08/21 16:36:00 [info] 1202#0: *216 [py:1225]   File "/opt/kong-python-plugins/kong-pluginserver.py", line 3, in <module>, context: ngx.timer
2023/08/21 16:36:00 [info] 1202#0: *216 [py:1225]     from kong_pdk import cli, context: ngx.timer
2023/08/21 16:36:00 [info] 1202#0: *216 [py:1225] ModuleNotFoundError: No module named 'kong_pdk', context: ngx.timer

I will fix this by modifying the way the kong_pdk package is installed or finding a way to override the Python settings.

4

[RESOLVED]

Adding this line before the kong PDK import line fixed things for me:

sys.path.append('/usr/local/lib/python3.10/dist-packages')

Perhaps there’s a cleaner way to do things (e.g. PYTHONPATH env var), but this seems like a decent temporary measure so I can work out other outstanding issues.