search

Kong / kong-python-pdk

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

kong.request.get_uri_captures() has no data #112

Closed cs1hsb closed 1 year ago

cs1hsb commented 1 year ago

Hi

Trying to use kong.request.get_uri_captures() as described here and here

(I think ngx.ctx.router_matches is out of date?)

I am doing this using a python plugin running in a KONG docker container.

When I try and call kong.request.get_uri_captures() I get the KONG error:

023/05/26 07:34:15 [error] 1256#0: *610 [kong] mp_rpc.lua:347 [py-test-capture-plugin] no data, client: 192.168.224.1, server: kong, request: "GET /apiv1/students/2000 HTTP/1.1", host: "localhost:8000"

My plugin works fine for other operations and functionality and the matched group regex path I have configured for the Route in kong.yml seems to correctly pass through requests to the plugin.

(I'm sure I'm also getting the mapping from lua to pyhon wrong for the return captures table but I would have thought I would progress past kong.request.get_uri_captures() in my plugin...)

I'm using kong:3.3.0-alpine docker hub image and I can see that kong-python-pluginserver 0.33 is running in the container.

Running KONG on debug with CMD ["kong", "start", "--vv"] hasn't given me any clues that I can see either.

Any help/advice greatly appreciated. thanks :)

FILES

py-test-capture-plugin.py

#!/usr/bin/env python3
import os
import kong_pdk.pdk.kong as kong

Schema = (
    {"message": {"type": "string"}},
)

version = '0.1.0'
priority = 0

class Plugin(object):
    def __init__(self, config):
        self.config = config

    def access(self, kong: kong.kong):
        try:
            kong.log("--------------------------------------------------------------------")

            kong.log("--------------------------")
            # errors here
            captures = kong.request.get_uri_captures()
            kong.log("--------------------------")
            named = captures.named
            kong.log("--------------------------")
            kong.log(str(named.items()));
            kong.log("--------------------------")

            # below all works when above code commented out
            kong.service.request.set_header("x-hello-from-python", kong.request.get_path())
            kong.service.request.set_header("x-python-pid", str(os.getpid()))
            params = {"wooId" : "132323323", "cardId" : "888888"}
            kong.log("--------------------------------------------------------------------")
            kong.service.request.set_query(params)
        except Exception as ex:
            kong.log.error(ex)

# add below section to allow this plugin optionally be running in a dedicated process
if __name__ == "__main__":
    from kong_pdk.cli import start_dedicated_server
    start_dedicated_server("hello-plugin", Plugin, version, priority, Schema)

kong.yml

_format_version: "3.0"

_transform: true

services:
  - name: test-api-1
    url: http://postman-echo.com/get
    plugins:
    routes:
      - name: test-api-1-students
        paths:
          - ~/apiv1/students/(?<studentid>\d+)
        plugins:
          - name: py-test-capture-plugin

Dockerfile-kong

FROM kong:3.3.0-alpine
USER root
# Example for Python
# PYTHONWARNINGS=ignore is needed to build gevent on Python 3.9
RUN apk update && \
    apk add python3 py3-pip python3-dev musl-dev libffi-dev gcc g++ file make && \
    PYTHONWARNINGS=ignore pip3 install kong-pdk

docker-compose.yml

version: '3.1'

services:

  kong:
    container_name: kong
    build:
      dockerfile: Dockerfile-kong
    volumes:
      # declarative db-less config
      - ./kong/config:/etc/kong/declarative
      # custom plugins
      - ./kong/py-plugins:/opt/conf/kong-py-plugins
    environment:
      # Use the config defined in kong.yml
      KONG_DATABASE: "off"
      KONG_DECLARATIVE_CONFIG: /etc/kong/declarative/kong.yml
      # Show all output in the terminal when running with Docker
      KONG_PROXY_ACCESS_LOG: /dev/stdout
      KONG_ADMIN_ACCESS_LOG: /dev/stdout
      KONG_PROXY_ERROR_LOG: /dev/stderr
      KONG_ADMIN_ERROR_LOG: /dev/stderr
      KONG_ADMIN_LISTEN: 0.0.0.0:8001, 0.0.0.0:8444 ssl
      # Enable the py plugin server
      KONG_PLUGINSERVER_NAMES: py
      KONG_PLUGINSERVER_PY_SOCKET: /usr/local/kong/python_pluginserver.sock
      KONG_PLUGINSERVER_PY_START_CMD: "/usr/bin/kong-python-pluginserver --no-lua-style --plugins-directory /opt/conf/kong-py-plugins"
      KONG_PLUGINSERVER_PY_QUERY_CMD: "/usr/bin/kong-python-pluginserver --no-lua-style --plugins-directory /opt/conf/kong-py-plugins --dump-all-plugins"
      # Allow plugins to be used. The plugin name is your py file name
      KONG_PLUGINS: "bundled, py-test-capture-plugin"
    ports:
      - 8000:8000
      - 8443:8443
      - 8001:8001
      - 8444:8444
    networks:
      - api-network

networks:
    api-network:

Test request

 curl -i --request GET 'http://localhost:8000/apiv1/students/2000'
cs1hsb commented 1 year ago

Hi - could someone help here please? Many thanks 🙏

StarlightIbuki commented 1 year ago

Sorry for the long delay, I'm looking into this.

StarlightIbuki commented 1 year ago

Is this issue reproducible every time you call the API? If so it's definitely a bug.

I skimmed the code and found that MessagePack/Kong both hide the error of ngx.socket:

https://github.com/markstinson/lua-MessagePack/blob/master/src/MessagePack.lua#LL1070C58-L1070C58

https://github.com/Kong/kong/blob/8bbad4344bd88ae6306407196d77d90dbfb8ad78/kong/runloop/plugin_servers/mp_rpc.lua#L220

So it's hard to say what is happening without reproducing the issue. (It could be a connection loss due to an instance crash)

I'll try your example but I don't have a chance recently. Most optimism estimated time to start debugging this would be near the end of this month.

fffonion commented 1 year ago

Hi @n99 seems some bug in your plugin caused the issue:

diff --git a/a.py b/a.py
index 09519a9..9f9fd5e 100644
--- a/a.py
+++ b/a.py
@@ -22,7 +22,7 @@ class Plugin(object):
             # errors here
             captures = kong.request.get_uri_captures()
             kong.log("--------------------------")
-            named = captures.named
+            named = captures["named"]
             kong.log("--------------------------")
             kong.log(str(named.items()));
             kong.log("--------------------------")
@@ -34,7 +34,7 @@ class Plugin(object):
             kong.log("--------------------------------------------------------------------")
             kong.service.request.set_query(params)
         except Exception as ex:
-            kong.log.error(ex)
+            kong.log.err(ex)

 # add below section to allow this plugin optionally be running in a dedicated process

In the meanwhile, we will improve our handling or python-pdk code, so the error could be actually returned to Kong for debugging.

cs1hsb commented 1 year ago

Many thanks indeed for taking the time to look at this. I've changed the plugin code as suggested above but still get the same error. Errors in the logs don't seem to show line numbers of the plugin.

Here is my plugin changed as per your suggestion:

#!/usr/bin/env python3
import os
import kong_pdk.pdk.kong as kong

Schema = (
    {"message": {"type": "string"}},
)

version = '0.1.0'
priority = 0

class Plugin(object):
    def __init__(self, config):
        self.config = config

    def access(self, kong: kong.kong):
        try:
            kong.log("--------------------------------------------------------------------1")

            kong.log("--------------------------2")
            captures = kong.request.get_uri_captures()
            kong.log("--------------------------3")
            named = captures["named"]
            kong.log("--------------------------4")
            kong.log(str(named.items()));
            kong.log("--------------------------5")

            kong.service.request.set_header("x-hello-from-python", kong.request.get_path())
            kong.service.request.set_header("x-python-pid", str(os.getpid()))
            kong.log("--------------------------------------------------------------------6")
        except Exception as ex:
            kong.log.err(ex)

# add below section to allow this plugin optionally be running in a dedicated process
if __name__ == "__main__":
    from kong_pdk.cli import start_dedicated_server
    start_dedicated_server("hello-plugin", Plugin, version, priority, Schema)

Here are the full logs incase something lurking somehwere:

2023/06/15 07:44:17 [verbose] Kong: 3.3.0
2023/06/15 07:44:17 [debug] ngx_lua: 10021
2023/06/15 07:44:17 [debug] nginx: 1021004
2023/06/15 07:44:17 [debug] Lua: LuaJIT 2.1.0-20220411
2023/06/15 07:44:17 [verbose] no config file found at /etc/kong/kong.conf
2023/06/15 07:44:17 [verbose] no config file found at /etc/kong.conf
2023/06/15 07:44:17 [verbose] no config file, skip loading
2023/06/15 07:44:17 [debug] reading environment variables
2023/06/15 07:44:17 [debug] KONG_PROXY_ERROR_LOG ENV found with "/dev/stderr"
2023/06/15 07:44:17 [debug] KONG_ADMIN_ACCESS_LOG ENV found with "/dev/stdout"
2023/06/15 07:44:17 [debug] KONG_ADMIN_ERROR_LOG ENV found with "/dev/stderr"
2023/06/15 07:44:17 [debug] KONG_PLUGINSERVER_PY_QUERY_CMD ENV found with "/usr/bin/kong-python-pluginserver --no-lua-style --plugins-directory /opt/conf/kong-py-plugins --dump-all-plugins"
2023/06/15 07:44:17 [debug] KONG_NGINX_DAEMON ENV found with "off"
2023/06/15 07:44:17 [debug] KONG_PLUGINSERVER_NAMES ENV found with "py"
2023/06/15 07:44:17 [debug] KONG_PLUGINSERVER_PY_SOCKET ENV found with "/usr/local/kong/python_pluginserver.sock"
2023/06/15 07:44:17 [debug] KONG_PLUGINSERVER_PY_START_CMD ENV found with "/usr/bin/kong-python-pluginserver --no-lua-style --plugins-directory /opt/conf/kong-py-plugins"
2023/06/15 07:44:17 [debug] KONG_PROXY_ACCESS_LOG ENV found with "/dev/stdout"
2023/06/15 07:44:17 [debug] KONG_PLUGINS ENV found with "bundled, py-test-capture-plugin"
2023/06/15 07:44:17 [debug] KONG_PREFIX ENV found with "/usr/local/kong"
2023/06/15 07:44:17 [debug] KONG_ADMIN_LISTEN ENV found with "0.0.0.0:8001, 0.0.0.0:8444 ssl"
2023/06/15 07:44:17 [debug] KONG_DECLARATIVE_CONFIG ENV found with "/etc/kong/declarative/kong.yml"
2023/06/15 07:44:17 [debug] KONG_DATABASE ENV found with "off"
2023/06/15 07:44:17 [debug] _debug_pg_ttl_cleanup_interval = 300
2023/06/15 07:44:17 [debug] admin_access_log = "/dev/stdout"
2023/06/15 07:44:17 [debug] admin_error_log = "/dev/stderr"
2023/06/15 07:44:17 [debug] admin_listen = {"0.0.0.0:8001","0.0.0.0:8444 ssl"}
2023/06/15 07:44:17 [debug] admin_ssl_cert = {}
2023/06/15 07:44:17 [debug] admin_ssl_cert_key = {}
2023/06/15 07:44:17 [debug] allow_debug_header = false
2023/06/15 07:44:17 [debug] anonymous_reports = true
2023/06/15 07:44:17 [debug] cassandra_contact_points = {"127.0.0.1"}
2023/06/15 07:44:17 [debug] cassandra_data_centers = {"dc1:2","dc2:3"}
2023/06/15 07:44:17 [debug] cassandra_keyspace = "kong"
2023/06/15 07:44:17 [debug] cassandra_lb_policy = "RequestRoundRobin"
2023/06/15 07:44:17 [debug] cassandra_port = 9042
2023/06/15 07:44:17 [debug] cassandra_read_consistency = "ONE"
2023/06/15 07:44:17 [debug] cassandra_refresh_frequency = 60
2023/06/15 07:44:17 [debug] cassandra_repl_factor = 1
2023/06/15 07:44:17 [debug] cassandra_repl_strategy = "SimpleStrategy"
2023/06/15 07:44:17 [debug] cassandra_schema_consensus_timeout = 10000
2023/06/15 07:44:17 [debug] cassandra_ssl = false
2023/06/15 07:44:17 [debug] cassandra_ssl_verify = false
2023/06/15 07:44:17 [debug] cassandra_timeout = 5000
2023/06/15 07:44:17 [debug] cassandra_username = "kong"
2023/06/15 07:44:17 [debug] cassandra_write_consistency = "ONE"
2023/06/15 07:44:17 [debug] client_body_buffer_size = "8k"
2023/06/15 07:44:17 [debug] client_ssl = false
2023/06/15 07:44:17 [debug] cluster_control_plane = "127.0.0.1:8005"
2023/06/15 07:44:17 [debug] cluster_data_plane_purge_delay = 1209600
2023/06/15 07:44:17 [debug] cluster_dp_labels = {}
2023/06/15 07:44:17 [debug] cluster_listen = {"0.0.0.0:8005"}
2023/06/15 07:44:17 [debug] cluster_max_payload = 4194304
2023/06/15 07:44:17 [debug] cluster_mtls = "shared"
2023/06/15 07:44:17 [debug] cluster_ocsp = "off"
2023/06/15 07:44:17 [debug] cluster_use_proxy = false
2023/06/15 07:44:17 [debug] database = "off"
2023/06/15 07:44:17 [debug] db_cache_ttl = 0
2023/06/15 07:44:17 [debug] db_cache_warmup_entities = {"services"}
2023/06/15 07:44:17 [debug] db_resurrect_ttl = 30
2023/06/15 07:44:17 [debug] db_update_frequency = 5
2023/06/15 07:44:17 [debug] db_update_propagation = 0
2023/06/15 07:44:17 [debug] declarative_config = "/etc/kong/declarative/kong.yml"
2023/06/15 07:44:17 [debug] dns_cache_size = 10000
2023/06/15 07:44:17 [debug] dns_error_ttl = 1
2023/06/15 07:44:17 [debug] dns_hostsfile = "/etc/hosts"
2023/06/15 07:44:17 [debug] dns_no_sync = false
2023/06/15 07:44:17 [debug] dns_not_found_ttl = 30
2023/06/15 07:44:17 [debug] dns_order = {"LAST","SRV","A","CNAME"}
2023/06/15 07:44:17 [debug] dns_resolver = {}
2023/06/15 07:44:17 [debug] dns_stale_ttl = 4
2023/06/15 07:44:17 [debug] error_default_type = "text/plain"
2023/06/15 07:44:17 [debug] headers = {"server_tokens","latency_tokens"}
2023/06/15 07:44:17 [debug] host_ports = {}
2023/06/15 07:44:17 [debug] kic = false
2023/06/15 07:44:17 [debug] lmdb_environment_path = "dbless.lmdb"
2023/06/15 07:44:17 [debug] lmdb_map_size = "128m"
2023/06/15 07:44:17 [debug] loaded_vaults = {env=true}
2023/06/15 07:44:17 [debug] log_level = "notice"
2023/06/15 07:44:17 [debug] lua_max_post_args = 100
2023/06/15 07:44:17 [debug] lua_max_req_headers = 100
2023/06/15 07:44:17 [debug] lua_max_resp_headers = 100
2023/06/15 07:44:17 [debug] lua_max_uri_args = 100
2023/06/15 07:44:17 [debug] lua_package_cpath = ""
2023/06/15 07:44:17 [debug] lua_package_path = "./?.lua;./?/init.lua;"
2023/06/15 07:44:17 [debug] lua_socket_pool_size = 30
2023/06/15 07:44:17 [debug] lua_ssl_protocols = "TLSv1.1 TLSv1.2 TLSv1.3"
2023/06/15 07:44:17 [debug] lua_ssl_trusted_certificate = {"/etc/ssl/certs/ca-certificates.crt"}
2023/06/15 07:44:17 [debug] lua_ssl_verify_depth = 1
2023/06/15 07:44:17 [debug] mem_cache_size = "128m"
2023/06/15 07:44:17 [debug] nginx_admin_client_body_buffer_size = "10m"
2023/06/15 07:44:17 [debug] nginx_admin_client_max_body_size = "10m"
2023/06/15 07:44:17 [debug] nginx_admin_directives = {{name="client_max_body_size",value="10m"},{name="client_body_buffer_size",value="10m"}}
2023/06/15 07:44:17 [debug] nginx_daemon = "off"
2023/06/15 07:44:17 [debug] nginx_events_directives = {{name="worker_connections",value="auto"},{name="multi_accept",value="on"}}
2023/06/15 07:44:17 [debug] nginx_events_multi_accept = "on"
2023/06/15 07:44:17 [debug] nginx_events_worker_connections = "auto"
2023/06/15 07:44:17 [debug] nginx_http_charset = "UTF-8"
2023/06/15 07:44:17 [debug] nginx_http_client_body_buffer_size = "8k"
2023/06/15 07:44:17 [debug] nginx_http_client_max_body_size = "0"
2023/06/15 07:44:17 [debug] nginx_http_directives = {{name="ssl_protocols",value="TLSv1.2 TLSv1.3"},{name="ssl_prefer_server_ciphers",value="off"},{name="ssl_session_tickets",value="on"},{name="ssl_session_timeout",value="1d"},{name="client_max_body_size",value="0"},{name="client_body_buffer_size",value="8k"},{name="lua_ssl_protocols",value="TLSv1.1 TLSv1.2 TLSv1.3"},{name="ssl_dhparam",value="ffdhe2048"},{name="lua_regex_cache_max_entries",value="8192"},{name="lua_regex_match_limit",value="100000"},{name="charset",value="UTF-8"}}
2023/06/15 07:44:17 [debug] nginx_http_lua_regex_cache_max_entries = "8192"
2023/06/15 07:44:17 [debug] nginx_http_lua_regex_match_limit = "100000"
2023/06/15 07:44:17 [debug] nginx_http_lua_ssl_protocols = "TLSv1.1 TLSv1.2 TLSv1.3"
2023/06/15 07:44:17 [debug] nginx_http_ssl_dhparam = "ffdhe2048"
2023/06/15 07:44:17 [debug] nginx_http_ssl_prefer_server_ciphers = "off"
2023/06/15 07:44:17 [debug] nginx_http_ssl_protocols = "TLSv1.2 TLSv1.3"
2023/06/15 07:44:17 [debug] nginx_http_ssl_session_tickets = "on"
2023/06/15 07:44:17 [debug] nginx_http_ssl_session_timeout = "1d"
2023/06/15 07:44:17 [debug] nginx_main_daemon = "off"
2023/06/15 07:44:17 [debug] nginx_main_directives = {{name="worker_rlimit_nofile",value="auto"},{name="daemon",value="off"},{name="user",value="kong kong"},{name="worker_processes",value="auto"}}
2023/06/15 07:44:17 [debug] nginx_main_user = "kong kong"
2023/06/15 07:44:17 [debug] nginx_main_worker_processes = "auto"
2023/06/15 07:44:17 [debug] nginx_main_worker_rlimit_nofile = "auto"
2023/06/15 07:44:17 [debug] nginx_proxy_directives = {{name="real_ip_header",value="X-Real-IP"},{name="real_ip_recursive",value="off"}}
2023/06/15 07:44:17 [debug] nginx_proxy_real_ip_header = "X-Real-IP"
2023/06/15 07:44:17 [debug] nginx_proxy_real_ip_recursive = "off"
2023/06/15 07:44:17 [debug] nginx_sproxy_directives = {}
2023/06/15 07:44:17 [debug] nginx_status_directives = {}
2023/06/15 07:44:17 [debug] nginx_stream_directives = {{name="ssl_protocols",value="TLSv1.2 TLSv1.3"},{name="ssl_prefer_server_ciphers",value="off"},{name="ssl_session_tickets",value="on"},{name="ssl_session_timeout",value="1d"},{name="lua_ssl_protocols",value="TLSv1.1 TLSv1.2 TLSv1.3"},{name="ssl_dhparam",value="ffdhe2048"}}
2023/06/15 07:44:17 [debug] nginx_stream_lua_ssl_protocols = "TLSv1.1 TLSv1.2 TLSv1.3"
2023/06/15 07:44:17 [debug] nginx_stream_ssl_dhparam = "ffdhe2048"
2023/06/15 07:44:17 [debug] nginx_stream_ssl_prefer_server_ciphers = "off"
2023/06/15 07:44:17 [debug] nginx_stream_ssl_protocols = "TLSv1.2 TLSv1.3"
2023/06/15 07:44:17 [debug] nginx_stream_ssl_session_tickets = "on"
2023/06/15 07:44:17 [debug] nginx_stream_ssl_session_timeout = "1d"
2023/06/15 07:44:17 [debug] nginx_supstream_directives = {}
2023/06/15 07:44:17 [debug] nginx_upstream_directives = {}
2023/06/15 07:44:17 [debug] nginx_user = "kong kong"
2023/06/15 07:44:17 [debug] nginx_worker_processes = "auto"
2023/06/15 07:44:17 [debug] opentelemetry_tracing = {"off"}
2023/06/15 07:44:17 [debug] opentelemetry_tracing_sampling_rate = 0.01
2023/06/15 07:44:17 [debug] pg_database = "kong"
2023/06/15 07:44:17 [debug] pg_host = "127.0.0.1"
2023/06/15 07:44:17 [debug] pg_max_concurrent_queries = 0
2023/06/15 07:44:17 [debug] pg_port = 5432
2023/06/15 07:44:17 [debug] pg_ro_ssl = false
2023/06/15 07:44:17 [debug] pg_ro_ssl_verify = false
2023/06/15 07:44:17 [debug] pg_semaphore_timeout = 60000
2023/06/15 07:44:17 [debug] pg_ssl = false
2023/06/15 07:44:17 [debug] pg_ssl_verify = false
2023/06/15 07:44:17 [debug] pg_timeout = 5000
2023/06/15 07:44:17 [debug] pg_user = "kong"
2023/06/15 07:44:17 [debug] plugins = {"bundled","py-test-capture-plugin"}
2023/06/15 07:44:17 [debug] pluginserver_names = {"py"}
2023/06/15 07:44:17 [debug] pluginserver_py_query_cmd = "/usr/bin/kong-python-pluginserver --no-lua-style --plugins-directory /opt/conf/kong-py-plugins --dump-all-plugins"
2023/06/15 07:44:17 [debug] pluginserver_py_socket = "/usr/local/kong/python_pluginserver.sock"
2023/06/15 07:44:17 [debug] pluginserver_py_start_cmd = "/usr/bin/kong-python-pluginserver --no-lua-style --plugins-directory /opt/conf/kong-py-plugins"
2023/06/15 07:44:17 [debug] port_maps = {}
2023/06/15 07:44:17 [debug] prefix = "/usr/local/kong"
2023/06/15 07:44:17 [debug] proxy_access_log = "/dev/stdout"
2023/06/15 07:44:17 [debug] proxy_error_log = "/dev/stderr"
2023/06/15 07:44:17 [debug] proxy_listen = {"0.0.0.0:8000 reuseport backlog=16384","0.0.0.0:8443 http2 ssl reuseport backlog=16384"}
2023/06/15 07:44:17 [debug] proxy_server_ssl_verify = true
2023/06/15 07:44:17 [debug] proxy_stream_access_log = "logs/access.log basic"
2023/06/15 07:44:17 [debug] proxy_stream_error_log = "logs/error.log"
2023/06/15 07:44:17 [debug] real_ip_header = "X-Real-IP"
2023/06/15 07:44:17 [debug] real_ip_recursive = "off"
2023/06/15 07:44:17 [debug] role = "traditional"
2023/06/15 07:44:17 [debug] router_flavor = "traditional_compatible"
2023/06/15 07:44:17 [debug] ssl_cert = {}
2023/06/15 07:44:17 [debug] ssl_cert_key = {}
2023/06/15 07:44:17 [debug] ssl_cipher_suite = "intermediate"
2023/06/15 07:44:17 [debug] ssl_ciphers = "ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384"
2023/06/15 07:44:17 [debug] ssl_dhparam = "ffdhe2048"
2023/06/15 07:44:17 [debug] ssl_prefer_server_ciphers = "on"
2023/06/15 07:44:17 [debug] ssl_protocols = "TLSv1.1 TLSv1.2 TLSv1.3"
2023/06/15 07:44:17 [debug] ssl_session_cache_size = "10m"
2023/06/15 07:44:17 [debug] ssl_session_tickets = "on"
2023/06/15 07:44:17 [debug] ssl_session_timeout = "1d"
2023/06/15 07:44:17 [debug] status_access_log = "off"
2023/06/15 07:44:17 [debug] status_error_log = "logs/status_error.log"
2023/06/15 07:44:17 [debug] status_listen = {"off"}
2023/06/15 07:44:17 [debug] status_ssl_cert = {}
2023/06/15 07:44:17 [debug] status_ssl_cert_key = {}
2023/06/15 07:44:17 [debug] stream_listen = {"off"}
2023/06/15 07:44:17 [debug] tracing_instrumentations = {"off"}
2023/06/15 07:44:17 [debug] tracing_sampling_rate = 0.01
2023/06/15 07:44:17 [debug] trusted_ips = {}
2023/06/15 07:44:17 [debug] untrusted_lua = "sandbox"
2023/06/15 07:44:17 [debug] untrusted_lua_sandbox_environment = {}
2023/06/15 07:44:17 [debug] untrusted_lua_sandbox_requires = {}
2023/06/15 07:44:17 [debug] upstream_keepalive_idle_timeout = 60
2023/06/15 07:44:17 [debug] upstream_keepalive_max_requests = 100
2023/06/15 07:44:17 [debug] upstream_keepalive_pool_size = 60
2023/06/15 07:44:17 [debug] vaults = {"bundled"}
2023/06/15 07:44:17 [debug] worker_consistency = "eventual"
2023/06/15 07:44:17 [debug] worker_state_update_frequency = 5
2023/06/15 07:44:17 [verbose] prefix in use: /usr/local/kong
2023/06/15 07:44:17 [verbose] preparing nginx prefix directory at /usr/local/kong
2023/06/15 07:44:17 [verbose] SSL enabled on proxy, no custom certificate set: using default certificates
2023/06/15 07:44:17 [verbose] generating proxy SSL certificate (/usr/local/kong/ssl/kong-default.crt) and key (/usr/local/kong/ssl/kong-default.key) for listener
2023/06/15 07:44:17 [verbose] generating proxy SSL certificate (/usr/local/kong/ssl/kong-default-ecdsa.crt) and key (/usr/local/kong/ssl/kong-default-ecdsa.key) for listener
2023/06/15 07:44:17 [verbose] SSL enabled on admin, no custom certificate set: using default certificates
2023/06/15 07:44:17 [verbose] generating admin SSL certificate (/usr/local/kong/ssl/admin-kong-default.crt) and key (/usr/local/kong/ssl/admin-kong-default.key) for listener
2023/06/15 07:44:17 [verbose] generating admin SSL certificate (/usr/local/kong/ssl/admin-kong-default-ecdsa.crt) and key (/usr/local/kong/ssl/admin-kong-default-ecdsa.key) for listener
2023/06/15 07:44:17 [verbose] generating trusted certs combined file in /usr/local/kong/.ca_combined
2023/06/15 07:44:17 [verbose] generating ffdhe2048 DH parameters
2023/06/15 07:44:17 [debug] searching for OpenResty 'nginx' executable
2023/06/15 07:44:17 [debug] nginx -v: 'nginx version: openresty/1.21.4.1'
2023/06/15 07:44:17 [debug] finding executable absolute path from $PATH...
2023/06/15 07:44:17 [debug] found OpenResty 'nginx' executable at /usr/local/bin/nginx
2023/06/15 07:44:17 [debug] testing nginx configuration: KONG_NGINX_CONF_CHECK=true /usr/local/bin/nginx -t -p /usr/local/kong -c nginx.conf
2023/06/15 07:44:17 [debug] loading subsystems migrations...
2023/06/15 07:44:17 [verbose] retrieving cache schema state...
2023/06/15 07:44:17 [verbose] schema state retrieved
2023/06/15 07:44:17 [debug] searching for OpenResty 'nginx' executable: [ip-address] - - [15/Jun/2023:07:44:26 +0000] "GET /apiv1/students/2000 HTTP/1.1" 200 426 "-" "curl/7.79.1"
2023/06/15 07:44:18 [notice] 1251#0: using the "epoll" event method
2023/06/15 07:44:18 [notice] 1251#0: openresty/1.21.4.1
2023/06/15 07:44:18 [notice] 1251#0: OS: Linux 5.15.49-linuxkit
2023/06/15 07:44:18 [notice] 1251#0: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2023/06/15 07:44:18 [notice] 1251#0: start worker processes
2023/06/15 07:44:18 [notice] 1251#0: start worker process 1257
2023/06/15 07:44:18 [notice] 1251#0: start worker process 1258
2023/06/15 07:44:18 [notice] 1251#0: start worker process 1259
2023/06/15 07:44:18 [notice] 1251#0: start worker process 1260
2023/06/15 07:44:18 [notice] 1259#0: *2 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.001 seconds), context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1260#0: *4 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.001 seconds), context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1257#0: *3 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.001 seconds), context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1259#0: *2 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.002 seconds), context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1260#0: *4 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.002 seconds), context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1257#0: *3 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.002 seconds), context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1259#0: *2 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.004 seconds), context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1260#0: *4 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.004 seconds), context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1257#0: *3 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.004 seconds), context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1258#0: *1 [lua] init.lua:240: purge(): [DB cache] purging (local) cache, context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1258#0: *1 [lua] init.lua:240: purge(): [DB cache] purging (local) cache, context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1258#0: *1 [kong] init.lua:521 declarative config loaded from /etc/kong/declarative/kong.yml, context: init_worker_by_lua*
2023/06/15 07:44:18 [notice] 1259#0: *2 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.008 seconds), context: init_worker_by_lua*
2023/06/15 07:44:19 [notice] 1257#0: *235 [kong] process.lua:252 Starting py, context: ngx.timer
2023/06/15 07:44:19 [crit] 1260#0: *303 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:44:19 [crit] 1258#0: *446 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:44:19 [crit] 1257#0: *448 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:44:19 [crit] 1259#0: *600 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:44:19 [crit] 1260#0: *303 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:44:19 [crit] 1258#0: *446 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:44:19 [crit] 1257#0: *448 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:44:19 [crit] 1259#0: *600 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:44:26 [notice] 1257#0: *610 [kong] mp_rpc.lua:157 [py-test-capture-plugin] --------------------------------------------------------------------1, client: [ip-address] , server: kong, request: "GET /apiv1/students/2000 HTTP/1.1", host: "localhost:8000"
2023/06/15 07:44:26 [notice] 1257#0: *610 [kong] mp_rpc.lua:157 [py-test-capture-plugin] --------------------------2, client: [ip-address] , server: kong, request: "GET /apiv1/students/2000 HTTP/1.1", host: "localhost:8000"
2023/06/15 07:44:26 [error] 1257#0: *610 [kong] mp_rpc.lua:347 [py-test-capture-plugin] no data, client: [ip-address] , server: kong, request: "GET /apiv1/students/2000 HTTP/1.1", host: "localhost:8000"

you can see that I only get as far as 

kong.log("--------------------------2")
cs1hsb commented 1 year ago

Also with the erroring code commented out as below

#!/usr/bin/env python3
import os
import kong_pdk.pdk.kong as kong

Schema = (
    {"message": {"type": "string"}},
)

version = '0.1.0'
priority = 0

class Plugin(object):
    def __init__(self, config):
        self.config = config

    def access(self, kong: kong.kong):
        try:
            kong.log("--------------------------------------------------------------------1")

            # kong.log("--------------------------2")
            # captures = kong.request.get_uri_captures()
            # kong.log("--------------------------3")
            # named = captures["named"]
            # kong.log("--------------------------4")
            # kong.log(str(named.items()));
            # kong.log("--------------------------5")

            kong.service.request.set_header("x-hello-from-python", kong.request.get_path())
            kong.service.request.set_header("x-python-pid", str(os.getpid()))
            kong.log("--------------------------------------------------------------------6")
        except Exception as ex:
            kong.log.err(ex)

# add below section to allow this plugin optionally be running in a dedicated process
if __name__ == "__main__":
    from kong_pdk.cli import start_dedicated_server
    start_dedicated_server("hello-plugin", Plugin, version, priority, Schema)

I get the logs

2023/06/15 07:51:06 [verbose] Kong: 3.3.0
2023/06/15 07:51:06 [debug] ngx_lua: 10021
2023/06/15 07:51:06 [debug] nginx: 1021004
2023/06/15 07:51:06 [debug] Lua: LuaJIT 2.1.0-20220411
2023/06/15 07:51:06 [verbose] no config file found at /etc/kong/kong.conf
2023/06/15 07:51:06 [verbose] no config file found at /etc/kong.conf
2023/06/15 07:51:06 [verbose] no config file, skip loading
2023/06/15 07:51:06 [debug] reading environment variables
2023/06/15 07:51:06 [debug] KONG_ADMIN_LISTEN ENV found with "0.0.0.0:8001, 0.0.0.0:8444 ssl"
2023/06/15 07:51:06 [debug] KONG_NGINX_DAEMON ENV found with "off"
2023/06/15 07:51:06 [debug] KONG_DATABASE ENV found with "off"
2023/06/15 07:51:06 [debug] KONG_PROXY_ACCESS_LOG ENV found with "/dev/stdout"
2023/06/15 07:51:06 [debug] KONG_PROXY_ERROR_LOG ENV found with "/dev/stderr"
2023/06/15 07:51:06 [debug] KONG_PLUGINSERVER_PY_QUERY_CMD ENV found with "/usr/bin/kong-python-pluginserver --no-lua-style --plugins-directory /opt/conf/kong-py-plugins --dump-all-plugins"
2023/06/15 07:51:06 [debug] KONG_ADMIN_ACCESS_LOG ENV found with "/dev/stdout"
2023/06/15 07:51:06 [debug] KONG_ADMIN_ERROR_LOG ENV found with "/dev/stderr"
2023/06/15 07:51:06 [debug] KONG_PLUGINSERVER_PY_START_CMD ENV found with "/usr/bin/kong-python-pluginserver --no-lua-style --plugins-directory /opt/conf/kong-py-plugins"
2023/06/15 07:51:06 [debug] KONG_PLUGINS ENV found with "bundled, py-test-capture-plugin"
2023/06/15 07:51:06 [debug] KONG_PREFIX ENV found with "/usr/local/kong"
2023/06/15 07:51:06 [debug] KONG_DECLARATIVE_CONFIG ENV found with "/etc/kong/declarative/kong.yml"
2023/06/15 07:51:06 [debug] KONG_PLUGINSERVER_PY_SOCKET ENV found with "/usr/local/kong/python_pluginserver.sock"
2023/06/15 07:51:06 [debug] KONG_PLUGINSERVER_NAMES ENV found with "py"
2023/06/15 07:51:06 [debug] _debug_pg_ttl_cleanup_interval = 300
2023/06/15 07:51:06 [debug] admin_access_log = "/dev/stdout"
2023/06/15 07:51:06 [debug] admin_error_log = "/dev/stderr"
2023/06/15 07:51:06 [debug] admin_listen = {"0.0.0.0:8001","0.0.0.0:8444 ssl"}
2023/06/15 07:51:06 [debug] admin_ssl_cert = {}
2023/06/15 07:51:06 [debug] admin_ssl_cert_key = {}
2023/06/15 07:51:06 [debug] allow_debug_header = false
2023/06/15 07:51:06 [debug] anonymous_reports = true
2023/06/15 07:51:06 [debug] cassandra_contact_points = {"127.0.0.1"}
2023/06/15 07:51:06 [debug] cassandra_data_centers = {"dc1:2","dc2:3"}
2023/06/15 07:51:06 [debug] cassandra_keyspace = "kong"
2023/06/15 07:51:06 [debug] cassandra_lb_policy = "RequestRoundRobin"
2023/06/15 07:51:06 [debug] cassandra_port = 9042
2023/06/15 07:51:06 [debug] cassandra_read_consistency = "ONE"
2023/06/15 07:51:06 [debug] cassandra_refresh_frequency = 60
2023/06/15 07:51:06 [debug] cassandra_repl_factor = 1
2023/06/15 07:51:06 [debug] cassandra_repl_strategy = "SimpleStrategy"
2023/06/15 07:51:06 [debug] cassandra_schema_consensus_timeout = 10000
2023/06/15 07:51:06 [debug] cassandra_ssl = false
2023/06/15 07:51:06 [debug] cassandra_ssl_verify = false
2023/06/15 07:51:06 [debug] cassandra_timeout = 5000
2023/06/15 07:51:06 [debug] cassandra_username = "kong"
2023/06/15 07:51:06 [debug] cassandra_write_consistency = "ONE"
2023/06/15 07:51:06 [debug] client_body_buffer_size = "8k"
2023/06/15 07:51:06 [debug] client_ssl = false
2023/06/15 07:51:06 [debug] cluster_control_plane = "127.0.0.1:8005"
2023/06/15 07:51:06 [debug] cluster_data_plane_purge_delay = 1209600
2023/06/15 07:51:06 [debug] cluster_dp_labels = {}
2023/06/15 07:51:06 [debug] cluster_listen = {"0.0.0.0:8005"}
2023/06/15 07:51:06 [debug] cluster_max_payload = 4194304
2023/06/15 07:51:06 [debug] cluster_mtls = "shared"
2023/06/15 07:51:06 [debug] cluster_ocsp = "off"
2023/06/15 07:51:06 [debug] cluster_use_proxy = false
2023/06/15 07:51:06 [debug] database = "off"
2023/06/15 07:51:06 [debug] db_cache_ttl = 0
2023/06/15 07:51:06 [debug] db_cache_warmup_entities = {"services"}
2023/06/15 07:51:06 [debug] db_resurrect_ttl = 30
2023/06/15 07:51:06 [debug] db_update_frequency = 5
2023/06/15 07:51:06 [debug] db_update_propagation = 0
2023/06/15 07:51:06 [debug] declarative_config = "/etc/kong/declarative/kong.yml"
2023/06/15 07:51:06 [debug] dns_cache_size = 10000
2023/06/15 07:51:06 [debug] dns_error_ttl = 1
2023/06/15 07:51:06 [debug] dns_hostsfile = "/etc/hosts"
2023/06/15 07:51:06 [debug] dns_no_sync = false
2023/06/15 07:51:06 [debug] dns_not_found_ttl = 30
2023/06/15 07:51:06 [debug] dns_order = {"LAST","SRV","A","CNAME"}
2023/06/15 07:51:06 [debug] dns_resolver = {}
2023/06/15 07:51:06 [debug] dns_stale_ttl = 4
2023/06/15 07:51:06 [debug] error_default_type = "text/plain"
2023/06/15 07:51:06 [debug] headers = {"server_tokens","latency_tokens"}
2023/06/15 07:51:06 [debug] host_ports = {}
2023/06/15 07:51:06 [debug] kic = false
2023/06/15 07:51:06 [debug] lmdb_environment_path = "dbless.lmdb"
2023/06/15 07:51:06 [debug] lmdb_map_size = "128m"
2023/06/15 07:51:06 [debug] loaded_vaults = {env=true}
2023/06/15 07:51:06 [debug] log_level = "notice"
2023/06/15 07:51:06 [debug] lua_max_post_args = 100
2023/06/15 07:51:06 [debug] lua_max_req_headers = 100
2023/06/15 07:51:06 [debug] lua_max_resp_headers = 100
2023/06/15 07:51:06 [debug] lua_max_uri_args = 100
2023/06/15 07:51:06 [debug] lua_package_cpath = ""
2023/06/15 07:51:06 [debug] lua_package_path = "./?.lua;./?/init.lua;"
2023/06/15 07:51:06 [debug] lua_socket_pool_size = 30
2023/06/15 07:51:06 [debug] lua_ssl_protocols = "TLSv1.1 TLSv1.2 TLSv1.3"
2023/06/15 07:51:06 [debug] lua_ssl_trusted_certificate = {"/etc/ssl/certs/ca-certificates.crt"}
2023/06/15 07:51:06 [debug] lua_ssl_verify_depth = 1
2023/06/15 07:51:06 [debug] mem_cache_size = "128m"
2023/06/15 07:51:06 [debug] nginx_admin_client_body_buffer_size = "10m"
2023/06/15 07:51:06 [debug] nginx_admin_client_max_body_size = "10m"
2023/06/15 07:51:06 [debug] nginx_admin_directives = {{name="client_body_buffer_size",value="10m"},{name="client_max_body_size",value="10m"}}
2023/06/15 07:51:06 [debug] nginx_daemon = "off"
2023/06/15 07:51:06 [debug] nginx_events_directives = {{name="worker_connections",value="auto"},{name="multi_accept",value="on"}}
2023/06/15 07:51:06 [debug] nginx_events_multi_accept = "on"
2023/06/15 07:51:06 [debug] nginx_events_worker_connections = "auto"
2023/06/15 07:51:06 [debug] nginx_http_charset = "UTF-8"
2023/06/15 07:51:06 [debug] nginx_http_client_body_buffer_size = "8k"
2023/06/15 07:51:06 [debug] nginx_http_client_max_body_size = "0"
2023/06/15 07:51:06 [debug] nginx_http_directives = {{name="ssl_dhparam",value="ffdhe2048"},{name="charset",value="UTF-8"},{name="client_max_body_size",value="0"},{name="lua_regex_match_limit",value="100000"},{name="lua_regex_cache_max_entries",value="8192"},{name="ssl_protocols",value="TLSv1.2 TLSv1.3"},{name="ssl_prefer_server_ciphers",value="off"},{name="ssl_session_tickets",value="on"},{name="ssl_session_timeout",value="1d"},{name="lua_ssl_protocols",value="TLSv1.1 TLSv1.2 TLSv1.3"},{name="client_body_buffer_size",value="8k"}}
2023/06/15 07:51:06 [debug] nginx_http_lua_regex_cache_max_entries = "8192"
2023/06/15 07:51:06 [debug] nginx_http_lua_regex_match_limit = "100000"
2023/06/15 07:51:06 [debug] nginx_http_lua_ssl_protocols = "TLSv1.1 TLSv1.2 TLSv1.3"
2023/06/15 07:51:06 [debug] nginx_http_ssl_dhparam = "ffdhe2048"
2023/06/15 07:51:06 [debug] nginx_http_ssl_prefer_server_ciphers = "off"
2023/06/15 07:51:06 [debug] nginx_http_ssl_protocols = "TLSv1.2 TLSv1.3"
2023/06/15 07:51:06 [debug] nginx_http_ssl_session_tickets = "on"
2023/06/15 07:51:06 [debug] nginx_http_ssl_session_timeout = "1d"
2023/06/15 07:51:06 [debug] nginx_main_daemon = "off"
2023/06/15 07:51:06 [debug] nginx_main_directives = {{name="daemon",value="off"},{name="worker_rlimit_nofile",value="auto"},{name="user",value="kong kong"},{name="worker_processes",value="auto"}}
2023/06/15 07:51:06 [debug] nginx_main_user = "kong kong"
2023/06/15 07:51:06 [debug] nginx_main_worker_processes = "auto"
2023/06/15 07:51:06 [debug] nginx_main_worker_rlimit_nofile = "auto"
2023/06/15 07:51:06 [debug] nginx_proxy_directives = {{name="real_ip_header",value="X-Real-IP"},{name="real_ip_recursive",value="off"}}
2023/06/15 07:51:06 [debug] nginx_proxy_real_ip_header = "X-Real-IP"
2023/06/15 07:51:06 [debug] nginx_proxy_real_ip_recursive = "off"
2023/06/15 07:51:06 [debug] nginx_sproxy_directives = {}
2023/06/15 07:51:06 [debug] nginx_status_directives = {}
2023/06/15 07:51:06 [debug] nginx_stream_directives = {{name="ssl_dhparam",value="ffdhe2048"},{name="ssl_protocols",value="TLSv1.2 TLSv1.3"},{name="ssl_prefer_server_ciphers",value="off"},{name="ssl_session_tickets",value="on"},{name="ssl_session_timeout",value="1d"},{name="lua_ssl_protocols",value="TLSv1.1 TLSv1.2 TLSv1.3"}}
2023/06/15 07:51:06 [debug] nginx_stream_lua_ssl_protocols = "TLSv1.1 TLSv1.2 TLSv1.3"
2023/06/15 07:51:06 [debug] nginx_stream_ssl_dhparam = "ffdhe2048"
2023/06/15 07:51:06 [debug] nginx_stream_ssl_prefer_server_ciphers = "off"
2023/06/15 07:51:06 [debug] nginx_stream_ssl_protocols = "TLSv1.2 TLSv1.3"
2023/06/15 07:51:06 [debug] nginx_stream_ssl_session_tickets = "on"
2023/06/15 07:51:06 [debug] nginx_stream_ssl_session_timeout = "1d"
2023/06/15 07:51:06 [debug] nginx_supstream_directives = {}
2023/06/15 07:51:06 [debug] nginx_upstream_directives = {}
2023/06/15 07:51:06 [debug] nginx_user = "kong kong"
2023/06/15 07:51:06 [debug] nginx_worker_processes = "auto"
2023/06/15 07:51:06 [debug] opentelemetry_tracing = {"off"}
2023/06/15 07:51:06 [debug] opentelemetry_tracing_sampling_rate = 0.01
2023/06/15 07:51:06 [debug] pg_database = "kong"
2023/06/15 07:51:06 [debug] pg_host = "127.0.0.1"
2023/06/15 07:51:06 [debug] pg_max_concurrent_queries = 0
2023/06/15 07:51:06 [debug] pg_port = 5432
2023/06/15 07:51:06 [debug] pg_ro_ssl = false
2023/06/15 07:51:06 [debug] pg_ro_ssl_verify = false
2023/06/15 07:51:06 [debug] pg_semaphore_timeout = 60000
2023/06/15 07:51:06 [debug] pg_ssl = false
2023/06/15 07:51:06 [debug] pg_ssl_verify = false
2023/06/15 07:51:06 [debug] pg_timeout = 5000
2023/06/15 07:51:06 [debug] pg_user = "kong"
2023/06/15 07:51:06 [debug] plugins = {"bundled","py-test-capture-plugin"}
2023/06/15 07:51:06 [debug] pluginserver_names = {"py"}
2023/06/15 07:51:06 [debug] pluginserver_py_query_cmd = "/usr/bin/kong-python-pluginserver --no-lua-style --plugins-directory /opt/conf/kong-py-plugins --dump-all-plugins"
2023/06/15 07:51:06 [debug] pluginserver_py_socket = "/usr/local/kong/python_pluginserver.sock"
2023/06/15 07:51:06 [debug] pluginserver_py_start_cmd = "/usr/bin/kong-python-pluginserver --no-lua-style --plugins-directory /opt/conf/kong-py-plugins"
2023/06/15 07:51:06 [debug] port_maps = {}
2023/06/15 07:51:06 [debug] prefix = "/usr/local/kong"
2023/06/15 07:51:06 [debug] proxy_access_log = "/dev/stdout"
2023/06/15 07:51:06 [debug] proxy_error_log = "/dev/stderr"
2023/06/15 07:51:06 [debug] proxy_listen = {"0.0.0.0:8000 reuseport backlog=16384","0.0.0.0:8443 http2 ssl reuseport backlog=16384"}
2023/06/15 07:51:06 [debug] proxy_server_ssl_verify = true
2023/06/15 07:51:06 [debug] proxy_stream_access_log = "logs/access.log basic"
2023/06/15 07:51:06 [debug] proxy_stream_error_log = "logs/error.log"
2023/06/15 07:51:06 [debug] real_ip_header = "X-Real-IP"
2023/06/15 07:51:06 [debug] real_ip_recursive = "off"
2023/06/15 07:51:06 [debug] role = "traditional"
2023/06/15 07:51:06 [debug] router_flavor = "traditional_compatible"
2023/06/15 07:51:06 [debug] ssl_cert = {}
2023/06/15 07:51:06 [debug] ssl_cert_key = {}
2023/06/15 07:51:06 [debug] ssl_cipher_suite = "intermediate"
2023/06/15 07:51:06 [debug] ssl_ciphers = "ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384"
2023/06/15 07:51:06 [debug] ssl_dhparam = "ffdhe2048"
2023/06/15 07:51:06 [debug] ssl_prefer_server_ciphers = "on"
2023/06/15 07:51:06 [debug] ssl_protocols = "TLSv1.1 TLSv1.2 TLSv1.3"
2023/06/15 07:51:06 [debug] ssl_session_cache_size = "10m"
2023/06/15 07:51:06 [debug] ssl_session_tickets = "on"
2023/06/15 07:51:06 [debug] ssl_session_timeout = "1d"
2023/06/15 07:51:06 [debug] status_access_log = "off"
2023/06/15 07:51:06 [debug] status_error_log = "logs/status_error.log"
2023/06/15 07:51:06 [debug] status_listen = {"off"}
2023/06/15 07:51:06 [debug] status_ssl_cert = {}
2023/06/15 07:51:06 [debug] status_ssl_cert_key = {}
2023/06/15 07:51:06 [debug] stream_listen = {"off"}
2023/06/15 07:51:06 [debug] tracing_instrumentations = {"off"}
2023/06/15 07:51:06 [debug] tracing_sampling_rate = 0.01
2023/06/15 07:51:06 [debug] trusted_ips = {}
2023/06/15 07:51:06 [debug] untrusted_lua = "sandbox"
2023/06/15 07:51:06 [debug] untrusted_lua_sandbox_environment = {}
2023/06/15 07:51:06 [debug] untrusted_lua_sandbox_requires = {}
2023/06/15 07:51:06 [debug] upstream_keepalive_idle_timeout = 60
2023/06/15 07:51:06 [debug] upstream_keepalive_max_requests = 100
2023/06/15 07:51:06 [debug] upstream_keepalive_pool_size = 60
2023/06/15 07:51:06 [debug] vaults = {"bundled"}
2023/06/15 07:51:06 [debug] worker_consistency = "eventual"
2023/06/15 07:51:06 [debug] worker_state_update_frequency = 5
2023/06/15 07:51:06 [verbose] prefix in use: /usr/local/kong
2023/06/15 07:51:06 [verbose] preparing nginx prefix directory at /usr/local/kong
2023/06/15 07:51:06 [verbose] SSL enabled on proxy, no custom certificate set: using default certificates
2023/06/15 07:51:06 [verbose] generating proxy SSL certificate (/usr/local/kong/ssl/kong-default.crt) and key (/usr/local/kong/ssl/kong-default.key) for listener
2023/06/15 07:51:06 [verbose] generating proxy SSL certificate (/usr/local/kong/ssl/kong-default-ecdsa.crt) and key (/usr/local/kong/ssl/kong-default-ecdsa.key) for listener
2023/06/15 07:51:06 [verbose] SSL enabled on admin, no custom certificate set: using default certificates
2023/06/15 07:51:06 [verbose] generating admin SSL certificate (/usr/local/kong/ssl/admin-kong-default.crt) and key (/usr/local/kong/ssl/admin-kong-default.key) for listener
2023/06/15 07:51:06 [verbose] generating admin SSL certificate (/usr/local/kong/ssl/admin-kong-default-ecdsa.crt) and key (/usr/local/kong/ssl/admin-kong-default-ecdsa.key) for listener
2023/06/15 07:51:06 [verbose] generating trusted certs combined file in /usr/local/kong/.ca_combined
2023/06/15 07:51:06 [verbose] generating ffdhe2048 DH parameters
2023/06/15 07:51:06 [debug] searching for OpenResty 'nginx' executable
2023/06/15 07:51:06 [debug] nginx -v: 'nginx version: openresty/1.21.4.1'
2023/06/15 07:51:06 [debug] finding executable absolute path from $PATH...
2023/06/15 07:51:06 [debug] found OpenResty 'nginx' executable at /usr/local/bin/nginx
2023/06/15 07:51:06 [debug] testing nginx configuration: KONG_NGINX_CONF_CHECK=true /usr/local/bin/nginx -t -p /usr/local/kong -c nginx.conf
2023/06/15 07:51:07 [debug] loading subsystems migrations...
2023/06/15 07:51:07 [verbose] retrieving cache schema state...
2023/06/15 07:51:07 [verbose] schema state retrieved
2023/06/15 07:51:08 [notice] 1251#0: using the "epoll" event method
2023/06/15 07:51:08 [notice] 1251#0: openresty/1.21.4.1
2023/06/15 07:51:08 [notice] 1251#0: OS: Linux 5.15.49-linuxkit
2023/06/15 07:51:08 [notice] 1251#0: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2023/06/15 07:51:08 [notice] 1251#0: start worker processes
2023/06/15 07:51:08 [notice] 1251#0: start worker process 1257
2023/06/15 07:51:08 [notice] 1251#0: start worker process 1258
2023/06/15 07:51:08 [notice] 1251#0: start worker process 1259
2023/06/15 07:51:08 [notice] 1251#0: start worker process 1260
2023/06/15 07:51:08 [notice] 1259#0: *3 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.001 seconds), context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1258#0: *2 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.001 seconds), context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1258#0: *2 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.002 seconds), context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1259#0: *3 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.002 seconds), context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1258#0: *2 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.004 seconds), context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1259#0: *3 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.004 seconds), context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1260#0: *4 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.001 seconds), context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1257#0: *1 [lua] init.lua:240: purge(): [DB cache] purging (local) cache, context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1257#0: *1 [lua] init.lua:240: purge(): [DB cache] purging (local) cache, context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1257#0: *1 [kong] init.lua:521 declarative config loaded from /etc/kong/declarative/kong.yml, context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1260#0: *4 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.002 seconds), context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1259#0: *3 [lua] globalpatches.lua:73: sleep(): executing a blocking 'sleep' (0.008 seconds), context: init_worker_by_lua*
2023/06/15 07:51:08 [notice] 1257#0: *159 [kong] process.lua:252 Starting py, context: ngx.timer
2023/06/15 07:51:08 [crit] 1257#0: *221 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:51:08 [crit] 1258#0: *387 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:51:08 [crit] 1260#0: *451 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:51:08 [crit] 1259#0: *600 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:51:08 [crit] 1257#0: *221 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:51:08 [crit] 1258#0: *387 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:51:08 [crit] 1260#0: *451 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:51:08 [crit] 1259#0: *600 connect() to unix:/usr/local/kong/python_pluginserver.sock failed (2: No such file or directory), context: ngx.timer
2023/06/15 07:51:13 [notice] 1258#0: *610 [kong] mp_rpc.lua:157 [py-test-capture-plugin] --------------------------------------------------------------------1, client: [ip-address] , server: kong, request: "GET /apiv1/students/2000 HTTP/1.1", host: "localhost:8000"
2023/06/15 07:51:07 [debug] searching for OpenResty 'nginx' executable[ip-address]  - - [15/Jun/2023:07:51:13 +0000] "GET /apiv1/students/2000 HTTP/1.1" 200 505 "-" "curl/7.79.1"
2023/06/15 07:51:13 [notice] 1258#0: *610 [kong] mp_rpc.lua:157 [py-test-capture-plugin] --------------------------------------------------------------------6, client: [ip-address] , server: kong, request: "GET /apiv1/students/2000 HTTP/1.1", host: "localhost:8000"

and I can see the headers being set in the request forwarded from kong..... :)

HTTP/1.1 200 OK
Content-Type: application/json; charset=utf-8
Content-Length: 505
Connection: keep-alive
Date: Thu, 15 Jun 2023 07:51:14 GMT
ETag: W/"1f9-0rW1iktvcAjVL0aN1se9zPPehxQ"
set-cookie: sails.sid=s%3AEqhZv802JEhcbf400wn-wqlW9_-Qg6oq.8%2FXzymRf4oNv%2BQH02met8GWpHlYoiawCOcNGip2fFLI; Path=/; HttpOnly
X-Kong-Upstream-Latency: 236
X-Kong-Proxy-Latency: 139
Via: kong/3.3.0

{
  "args": {},
  "headers": {
    "x-forwarded-proto": "http",
    "x-forwarded-port": "80",
    "host": "postman-echo.com",
    "x-amzn-trace-id": "Root=1-648ac2f2-3254b73d4042dc002c425a78",
    "x-forwarded-host": "localhost",
    "x-forwarded-path": "/apiv1/students/2000",
    "x-forwarded-prefix": "/apiv1/students/2000",
    "user-agent": "curl/7.79.1",
    "accept": "*/*",

---
    "x-hello-from-python": "/apiv1/students/2000",
    "x-python-pid": "1261"
---

  },
  "url": "http://postman-echo.com/get"
}
khangt1k25 commented 1 year ago

Have you have the way to fix it yet? I am also face this problem too. kong.log will output nodata. 

service = kong.router.get_service()
kong.log.crit(service.id)
fffonion commented 1 year ago

please see the attached PR for the fix https://github.com/Kong/kong-python-pdk/pull/117

cs1hsb commented 1 year ago

@fffonion - thanks sorry - I thought you had found a bug in the python plugin I had myself written that was the actual issue.

I will eagerly await the approval of the pull request. :)

(Sorry not sure how I get the fix added to my docker setup?)

thanks

fffonion commented 1 year ago

Fixed in 0.34, closing this now as finished. Please re-open if the issue still exists.