Kong: Kong plugins doesn't get executed unless kong reloaded or restarted

[rucciva]

Please read the CONTRIBUTING.md guidelines to learn on which channels you can
seek for help and ask general questions:

https://github.com/Kong/kong/blob/master/CONTRIBUTING.md#where-to-seek-for-help

Summary

After creating around 72 services, 72 route, 3*72 route's plugins, 72 consumer, 72 routes + consumers plugins, when sending the request to any route, the plugins won't get executed. Only after kong reload or restart does the plugins get executed

Steps To Reproduce

1. git clone https://github.com/rucciva/kong-plugin-bug
2. cd kong-plugin-bug && docker-compose up -d && docker-compose logs -f set-up
3. wait until set-up service done. all 72 routes are available via /api-[1-72]/v1.0.0 path
4. invoke any route, e.g. curl localhost:8000/api-3/v1.0.0. No plugins get executed
5. wait for minutes
6. re-invoking the route still produce the same result
7. reload or restart via docker-compose exec kong kong reload or docker-compose exec kong kong restart
8. re-invoking the api, now the plugins get executed

Additional Details & Logs

• Kong version (1.0.0)

• Kong debug-level startup logs

  Attaching to kong-plugin-bug_kong_1
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] globalpatches.lua:9: installing the globalpatches
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] globalpatches.lua:201: randomseed(): seeding PRNG from OpenSSL RAND_bytes()
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] globalpatches.lua:227: randomseed(): random seed: 755925148178 for worker nb 0
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:441: init(): [dns-client] (re)configuring dns client
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:446: init(): [dns-client] staleTtl = 4
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:449: init(): [dns-client] validTtl = nil
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:453: init(): [dns-client] noSynchronisation = false
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:472: init(): [dns-client] query order = LAST, SRV, A, CNAME
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:512: init(): [dns-client] adding A-record from 'hosts' file: 411d6300358d = 172.28.0.4
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-mcastprefix = [ff00::0]
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-localnet = [fe00::0]
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:512: init(): [dns-client] adding A-record from 'hosts' file: localhost = 127.0.0.1
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: localhost = [::1]
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-localhost = [::1]
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-loopback = [::1]
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-allnodes = [ff02::1]
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-allrouters = [ff02::2]
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:571: init(): [dns-client] nameserver 127.0.0.11
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:576: init(): [dns-client] attempts = 5
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:585: init(): [dns-client] timeout = 2000 ms
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:589: init(): [dns-client] ndots = 0
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:591: init(): [dns-client] search = 
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:597: init(): [dns-client] badTtl = 30 s
  kong_1      | 2019/01/12 15:03:10 [debug] 1#0: [lua] client.lua:599: init(): [dns-client] emptyTtl = 1 s
  kong_1      | 2019/01/12 15:03:11 [error] 1#0: init_by_lua error: /usr/local/share/lua/5.1/kong/init.lua:284: new migrations available; run 'kong migrations list'
  kong_1      | stack traceback:
  kong_1      |  [C]: in function 'error'
  kong_1      |  /usr/local/share/lua/5.1/kong/init.lua:284: in function 'init'
  kong_1      |  init_by_lua:3: in main chunk
  kong_1      | nginx: [error] init_by_lua error: /usr/local/share/lua/5.1/kong/init.lua:284: new migrations available; run 'kong migrations list'
  kong_1      | stack traceback:
  kong_1      |  [C]: in function 'error'
  kong_1      |  /usr/local/share/lua/5.1/kong/init.lua:284: in function 'init'
  kong_1      |  init_by_lua:3: in main chunk
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] globalpatches.lua:9: installing the globalpatches
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] globalpatches.lua:201: randomseed(): seeding PRNG from OpenSSL RAND_bytes()
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] globalpatches.lua:227: randomseed(): random seed: 129251184150 for worker nb 0
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:441: init(): [dns-client] (re)configuring dns client
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:446: init(): [dns-client] staleTtl = 4
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:449: init(): [dns-client] validTtl = nil
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:453: init(): [dns-client] noSynchronisation = false
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:472: init(): [dns-client] query order = LAST, SRV, A, CNAME
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:512: init(): [dns-client] adding A-record from 'hosts' file: 411d6300358d = 172.28.0.3
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-mcastprefix = [ff00::0]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-localnet = [fe00::0]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:512: init(): [dns-client] adding A-record from 'hosts' file: localhost = 127.0.0.1
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: localhost = [::1]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-localhost = [::1]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-loopback = [::1]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-allnodes = [ff02::1]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-allrouters = [ff02::2]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:571: init(): [dns-client] nameserver 127.0.0.11
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:576: init(): [dns-client] attempts = 5
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:585: init(): [dns-client] timeout = 2000 ms
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:589: init(): [dns-client] ndots = 0
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:591: init(): [dns-client] search = 
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:597: init(): [dns-client] badTtl = 30 s
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:599: init(): [dns-client] emptyTtl = 1 s
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:31: check_db_against_config(): Discovering used plugins
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:441: init(): [dns-client] (re)configuring dns client
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:446: init(): [dns-client] staleTtl = 4
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:449: init(): [dns-client] validTtl = nil
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:453: init(): [dns-client] noSynchronisation = false
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:472: init(): [dns-client] query order = LAST, SRV, A, CNAME
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:512: init(): [dns-client] adding A-record from 'hosts' file: 411d6300358d = 172.28.0.3
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-mcastprefix = [ff00::0]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-localnet = [fe00::0]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:512: init(): [dns-client] adding A-record from 'hosts' file: localhost = 127.0.0.1
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: localhost = [::1]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-localhost = [::1]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-loopback = [::1]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-allnodes = [ff02::1]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:527: init(): [dns-client] adding AAAA-record from 'hosts' file: ip6-allrouters = [ff02::2]
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:571: init(): [dns-client] nameserver 127.0.0.11
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:576: init(): [dns-client] attempts = 5
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:585: init(): [dns-client] timeout = 2000 ms
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:589: init(): [dns-client] ndots = 0
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:591: init(): [dns-client] search = 
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:597: init(): [dns-client] badTtl = 30 s
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] client.lua:599: init(): [dns-client] emptyTtl = 1 s
  kong_1      | 2019/01/12 15:03:14 [info] 1#0: [lua] mesh.lua:62: init(): initialising cluster ca...
  kong_1      | 2019/01/12 15:03:14 [info] 1#0: [lua] mesh.lua:122: init(): cluster ca initialised
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] mesh.lua:123: init(): mesh alpn is 'com.konghq/service-mesh/1/2rovCcKsVg5kXM2aSh7VNs5FaTjaL1LxyF7r6Le6CCY='
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] mesh.lua:124: init(): node certificate generated, fingerprint is 'GMOLAWzVov3ewIfjEed3BLCtRMdjyMQrIR3JBTP2ugI='
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] mesh.lua:173: init(): SSL_CTX* mesh ALPN selection setup complete
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: response-transformer
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: oauth2
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:273: load_plugin_schemas(): Loading custom plugin entity: 'oauth2.oauth2_credentials'
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:273: load_plugin_schemas(): Loading custom plugin entity: 'oauth2.oauth2_authorization_codes'
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:273: load_plugin_schemas(): Loading custom plugin entity: 'oauth2.oauth2_tokens'
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: acl
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:273: load_plugin_schemas(): Loading custom plugin entity: 'acl.acls'
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: correlation-id
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: pre-function
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: jwt
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:273: load_plugin_schemas(): Loading custom plugin entity: 'jwt.jwt_secrets'
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: cors
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: ip-restriction
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: basic-auth
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:273: load_plugin_schemas(): Loading custom plugin entity: 'basic-auth.basicauth_credentials'
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: key-auth
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:273: load_plugin_schemas(): Loading custom plugin entity: 'key-auth.keyauth_credentials'
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: rate-limiting
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: request-transformer
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: http-log
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: file-log
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: hmac-auth
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:273: load_plugin_schemas(): Loading custom plugin entity: 'hmac-auth.hmacauth_credentials'
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: ldap-auth
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: datadog
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: tcp-log
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: zipkin
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: post-function
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: request-size-limiting
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: bot-detection
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: syslog
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: loggly
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: azure-functions
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: udp-log
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: response-ratelimiting
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: aws-lambda
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: statsd
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: prometheus
  kong_1      | 2019/01/12 15:03:14 [debug] 1#0: [lua] plugins.lua:259: load_plugin_schemas(): Loading plugin: request-termination
  kong_1      | 2019/01/12 15:03:14 [notice] 1#0: using the "epoll" event method
  kong_1      | 2019/01/12 15:03:14 [notice] 1#0: openresty/1.13.6.2
  kong_1      | 2019/01/12 15:03:14 [notice] 1#0: built by gcc 6.3.0 (Alpine 6.3.0) 
  kong_1      | 2019/01/12 15:03:14 [notice] 1#0: OS: Linux 4.9.125-linuxkit
  kong_1      | 2019/01/12 15:03:14 [notice] 1#0: getrlimit(RLIMIT_NOFILE): 1048576:1048576
  kong_1      | 2019/01/12 15:03:14 [notice] 1#0: start worker processes
  kong_1      | 2019/01/12 15:03:14 [notice] 1#0: start worker process 36
  kong_1      | 2019/01/12 15:03:14 [notice] 1#0: start worker process 37
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] globalpatches.lua:201: randomseed(): seeding PRNG from OpenSSL RAND_bytes()
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] globalpatches.lua:227: randomseed(): random seed: 171244254243 for worker nb 0
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] globalpatches.lua:201: randomseed(): seeding PRNG from OpenSSL RAND_bytes()
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] globalpatches.lua:227: randomseed(): random seed: 721031602542 for worker nb 1
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] events.lua:192: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=36, data=nil
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] events.lua:192: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=37, data=nil
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "pre-function": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "opentracing": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "bot-detection": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "cors": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "jwt": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "oauth2": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "key-auth": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "ldap-auth": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "basic-auth": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "hmac-auth": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "ip-restriction": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "request-size-limiting": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "acl": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "rate-limiting": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "pre-function": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "response-ratelimiting": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "opentracing": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "request-transformer": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "bot-detection": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "cors": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "response-transformer": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "jwt": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "aws-lambda": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "oauth2": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "azure-functions": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "key-auth": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "prometheus": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "ldap-auth": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "basic-auth": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "http-log": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "hmac-auth": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "statsd": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "ip-restriction": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "request-size-limiting": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "acl": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "datadog": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "rate-limiting": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "file-log": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "udp-log": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "tcp-log": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "loggly": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "syslog": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "request-termination": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "correlation-id": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *1 [lua] base_plugin.lua:13: init_worker(): executing plugin "post-function": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "response-ratelimiting": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "request-transformer": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "response-transformer": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "aws-lambda": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "azure-functions": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "prometheus": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "http-log": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "statsd": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "datadog": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "file-log": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "udp-log": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "tcp-log": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "loggly": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "syslog": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "request-termination": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "correlation-id": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *2 [lua] base_plugin.lua:13: init_worker(): executing plugin "post-function": init_worker
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *3 [lua] balancer.lua:734: init(): initialized 0 balancer(s), 0 error(s)
  kong_1      | 2019/01/12 15:03:14 [debug] 37#0: *9 [lua] balancer.lua:734: init(): initialized 0 balancer(s), 0 error(s)
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:234: Loading Admin API endpoints
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: response-transformer
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:305: Loading API endpoints for plugin: oauth2
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:305: Loading API endpoints for plugin: acl
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: correlation-id
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: pre-function
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:305: Loading API endpoints for plugin: jwt
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: cors
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: ip-restriction
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:305: Loading API endpoints for plugin: basic-auth
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:305: Loading API endpoints for plugin: key-auth
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: rate-limiting
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: request-transformer
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: http-log
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: file-log
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:305: Loading API endpoints for plugin: hmac-auth
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: ldap-auth
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: datadog
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: tcp-log
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: zipkin
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: post-function
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: request-size-limiting
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: bot-detection
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: syslog
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: loggly
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: azure-functions
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: udp-log
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: response-ratelimiting
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: aws-lambda
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: statsd
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:305: Loading API endpoints for plugin: prometheus
  kong_1      | 2019/01/12 15:03:14 [debug] 36#0: *10 [lua] init.lua:313: No API endpoints loaded for plugin: request-termination
  

• Kong error logs

• Kong configuration

  {"plugins":{"enabled_in_cluster":["cors","correlation-id","oauth2","acl"],"available_on_server":{"response-transformer":true,"oauth2":true,"acl":true,"correlation-id":true,"pre-function":true,"jwt":true,"cors":true,"ip-restriction":true,"basic-auth":true,"key-auth":true,"rate-limiting":true,"request-transformer":true,"http-log":true,"file-log":true,"hmac-auth":true,"ldap-auth":true,"datadog":true,"tcp-log":true,"zipkin":true,"post-function":true,"request-size-limiting":true,"bot-detection":true,"syslog":true,"loggly":true,"azure-functions":true,"udp-log":true,"response-ratelimiting":true,"aws-lambda":true,"statsd":true,"prometheus":true,"request-termination":true}},"tagline":"Welcome to kong","configuration":{"plugins":["bundled"],"admin_ssl_enabled":false,"lua_ssl_verify_depth":1,"trusted_ips":{},"prefix":"\/usr\/local\/kong","loaded_plugins":{"response-transformer":true,"request-termination":true,"prometheus":true,"ip-restriction":true,"pre-function":true,"jwt":true,"cors":true,"statsd":true,"basic-auth":true,"key-auth":true,"ldap-auth":true,"aws-lambda":true,"http-log":true,"response-ratelimiting":true,"hmac-auth":true,"request-size-limiting":true,"datadog":true,"tcp-log":true,"zipkin":true,"post-function":true,"bot-detection":true,"acl":true,"loggly":true,"syslog":true,"azure-functions":true,"udp-log":true,"file-log":true,"request-transformer":true,"correlation-id":true,"rate-limiting":true,"oauth2":true},"cassandra_username":"kong","ssl_cert_key":"\/usr\/local\/kong\/ssl\/kong-default.key","dns_resolver":{},"pg_user":"kong","mem_cache_size":"128m","ssl_ciphers":"ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256","nginx_admin_directives":{},"nginx_http_directives":[{"value":"prometheus_metrics 5m","name":"lua_shared_dict"}],"pg_host":"postgres","nginx_acc_logs":"\/usr\/local\/kong\/logs\/access.log","proxy_listen":["0.0.0.0:8000","0.0.0.0:8443 ssl"],"client_ssl_cert_default":"\/usr\/local\/kong\/ssl\/kong-default.crt","ssl_cert_key_default":"\/usr\/local\/kong\/ssl\/kong-default.key","db_update_frequency":5,"db_update_propagation":0,"stream_listen":["off"],"nginx_err_logs":"\/usr\/local\/kong\/logs\/error.log","cassandra_port":9042,"dns_order":["LAST","SRV","A","CNAME"],"dns_error_ttl":1,"headers":["server_tokens","latency_tokens"],"dns_stale_ttl":4,"nginx_optimizations":true,"origins":{},"database":"postgres","pg_database":"kong","nginx_worker_processes":"auto","lua_package_cpath":"","admin_acc_logs":"\/usr\/local\/kong\/logs\/admin_access.log","lua_package_path":".\/?.lua;.\/?\/init.lua;","nginx_pid":"\/usr\/local\/kong\/pids\/nginx.pid","upstream_keepalive":60,"admin_access_log":"\/dev\/stdout","cassandra_data_centers":["dc1:2","dc2:3"],"client_ssl":false,"proxy_listeners":[{"transparent":false,"ssl":false,"ip":"0.0.0.0","proxy_protocol":false,"port":8000,"http2":false,"listener":"0.0.0.0:8000"},{"transparent":false,"ssl":true,"ip":"0.0.0.0","proxy_protocol":false,"port":8443,"http2":false,"listener":"0.0.0.0:8443 ssl"}],"proxy_ssl_enabled":true,"cassandra_ssl":false,"client_max_body_size":"0","enabled_headers":{"latency_tokens":true,"X-Kong-Proxy-Latency":true,"Via":true,"server_tokens":true,"Server":true,"X-Kong-Upstream-Latency":true,"X-Kong-Upstream-Status":false},"dns_no_sync":false,"proxy_error_log":"\/dev\/stderr","db_resurrect_ttl":30,"admin_ssl_cert_default":"\/usr\/local\/kong\/ssl\/admin-kong-default.crt","cassandra_consistency":"ONE","db_cache_ttl":0,"admin_error_log":"\/dev\/stderr","pg_ssl_verify":false,"dns_not_found_ttl":30,"pg_ssl":false,"lua_socket_pool_size":30,"cassandra_schema_consensus_timeout":10000,"cassandra_repl_strategy":"SimpleStrategy","nginx_kong_stream_conf":"\/usr\/local\/kong\/nginx-kong-stream.conf","pg_timeout":5000,"error_default_type":"text\/plain","nginx_proxy_directives":{},"kong_env":"\/usr\/local\/kong\/.kong_env","real_ip_header":"X-Real-IP","dns_hostsfile":"\/etc\/hosts","admin_listeners":[{"transparent":false,"ssl":false,"ip":"0.0.0.0","proxy_protocol":false,"port":8001,"http2":false,"listener":"0.0.0.0:8001"}],"cassandra_timeout":5000,"ssl_cert":"\/usr\/local\/kong\/ssl\/kong-default.crt","ssl_cipher_suite":"modern","admin_ssl_cert_key_default":"\/usr\/local\/kong\/ssl\/admin-kong-default.key","cassandra_ssl_verify":false,"proxy_access_log":"\/dev\/stdout","cassandra_contact_points":["127.0.0.1"],"real_ip_recursive":"off","cassandra_repl_factor":1,"client_ssl_cert_key_default":"\/usr\/local\/kong\/ssl\/kong-default.key","nginx_daemon":"off","anonymous_reports":true,"stream_listeners":{},"log_level":"debug","pg_port":5432,"nginx_kong_conf":"\/usr\/local\/kong\/nginx-kong.conf","client_body_buffer_size":"8k","ssl_preread_enabled":true,"cassandra_lb_policy":"RequestRoundRobin","ssl_cert_csr_default":"\/usr\/local\/kong\/ssl\/kong-default.csr","cassandra_keyspace":"kong","ssl_cert_default":"\/usr\/local\/kong\/ssl\/kong-default.crt","nginx_conf":"\/usr\/local\/kong\/nginx.conf","admin_listen":["0.0.0.0:8001"]},"version":"1.0.0","node_id":"03d9ae18-89b6-4876-b138-68ed706c58d9","lua_version":"LuaJIT 2.1.0-beta3","prng_seeds":{"pid: 36":171244254243,"pid: 37":721031602542,"pid: 1":129251184150},"timers":{"pending":5,"running":0},"hostname":"411d6300358d"}
  

• Operating system: Linux (docker)

[rucciva]

Shed some light. the behaviour is only found when creating plugins with PUT method. even at 1 route 1 service 3 plugins, the plugins will not get executed. But after creating the plugins with POST method, the plugins get executed normally. i notice that the PUT method in 1.0.0 is slightly different than in 0.14.x.

Steps To Reproduce

1. git clone https://github.com/rucciva/kong-plugin-bug
2. cd kong-plugin-bug && git checkout create-plugin-with-post && docker-compose up -d && docker-compose logs -f set-up
3. wait until set-up service done. all 72 routes are available via /api-[1-72]/v1.0.0 path
4. invoke any route, e.g. curl localhost:8000/api-3/v1.0.0. the plugins is executed

[hishamhm]

@rucciva Thank you for the investigation! I sent a PR to fix this.

[thibaultcha]

We just release 1.0.2, which should address this issue. Thanks for the report @rucciva!