go plugins are not called occasionally

[ealogar]

I already reported this at kong main repo:
Kong/kong#5586

But I think that the problem is at pluginserver side as the plugin iterator are being executed (i have added myself a trace on function Kong.access() in init.lua and I can say that the go plugin is being returned (as first) but afterwards the Access method is not called.
No errors appear it's just that the kong event is being lost and without saying anything.

This issue makes gopluginserver unusable for production

Can you have a look at it?

[mfeledyn]

I have seen this also, and I was able to reproduce. AFAIK problem seems related to networks names resolution problem (DNS misconfiguration) leading to go plugin not being called.

[az2az]

my go-hello plugin was added without saying anything,how can I resolve it.thanks

[mfeledyn]

You may have a look at kong error.log, and change log level if needed (in that case restart kong).
Can you explain what you have done to add your plugin ?

[az2az]

I have changed log level to debug.the log display go-hello is loaded.and go-pluginserver is started.no any errors. I have used 'go build -buildmode=plugin go-hello.go' to compiled plugin on centos7.and added it to kong.

kong config set like this:

plugins = bundled,go-hello
go_pluginserver_exe = /usr/local/bin/go-pluginserver
go_plugins_dir = /go/master
nginx_user = root root #start nginx use root,use nobody will fail

the error.log like this:

2020/04/16 16:02:20 [debug] 21460#0: [lua] globalpatches.lua:10: installing the globalpatches
2020/04/16 16:02:20 [debug] 21460#0: [lua] globalpatches.lua:243: randomseed(): seeding PRNG from OpenSSL RAND_bytes()
2020/04/16 16:02:20 [debug] 21460#0: [lua] globalpatches.lua:269: randomseed(): random seed: 248215274949 for worker nb 0
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:449: init(): [dns-client] (re)configuring dns client
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:454: init(): [dns-client] staleTtl = 4
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:457: init(): [dns-client] validTtl = nil
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:461: init(): [dns-client] noSynchronisation = false
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:480: init(): [dns-client] query order = LAST, SRV, A, CNAME
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:535: init(): [dns-client] adding AAAA-record from 'hosts' file: localhost6.localdomain6 = [::1]
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:520: init(): [dns-client] adding A-record from 'hosts' file: monkserver = 172.24.130.247
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:535: init(): [dns-client] adding AAAA-record from 'hosts' file: localhost6 = [::1]
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:520: init(): [dns-client] adding A-record from 'hosts' file: localhost4 = 127.0.0.1
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:520: init(): [dns-client] adding A-record from 'hosts' file: localhost.localdomain = 127.0.0.1
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:535: init(): [dns-client] adding AAAA-record from 'hosts' file: localhost.localdomain = [::1]
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:520: init(): [dns-client] adding A-record from 'hosts' file: localhost4.localdomain4 = 127.0.0.1
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:520: init(): [dns-client] adding A-record from 'hosts' file: localhost = 127.0.0.1
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:535: init(): [dns-client] adding AAAA-record from 'hosts' file: localhost = [::1]
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:579: init(): [dns-client] nameserver 100.100.2.136
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:579: init(): [dns-client] nameserver 100.100.2.138
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:584: init(): [dns-client] attempts = 5
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:593: init(): [dns-client] timeout = 2000 ms
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:597: init(): [dns-client] ndots = 1
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:599: init(): [dns-client] search =
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:605: init(): [dns-client] badTtl = 1 s
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:607: init(): [dns-client] emptyTtl = 30 s
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:125: check_db_against_config(): Discovering used plugins
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:449: init(): [dns-client] (re)configuring dns client
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:454: init(): [dns-client] staleTtl = 4
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:457: init(): [dns-client] validTtl = nil
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:461: init(): [dns-client] noSynchronisation = false
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:480: init(): [dns-client] query order = LAST, SRV, A, CNAME
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:535: init(): [dns-client] adding AAAA-record from 'hosts' file: localhost6.localdomain6 = [::1]
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:520: init(): [dns-client] adding A-record from 'hosts' file: monkserver = 172.24.130.247
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:535: init(): [dns-client] adding AAAA-record from 'hosts' file: localhost6 = [::1]
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:520: init(): [dns-client] adding A-record from 'hosts' file: localhost4 = 127.0.0.1
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:520: init(): [dns-client] adding A-record from 'hosts' file: localhost.localdomain = 127.0.0.1
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:535: init(): [dns-client] adding AAAA-record from 'hosts' file: localhost.localdomain = [::1]
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:520: init(): [dns-client] adding A-record from 'hosts' file: localhost4.localdomain4 = 127.0.0.1
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:520: init(): [dns-client] adding A-record from 'hosts' file: localhost = 127.0.0.1
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:535: init(): [dns-client] adding AAAA-record from 'hosts' file: localhost = [::1]
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:579: init(): [dns-client] nameserver 100.100.2.136
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:579: init(): [dns-client] nameserver 100.100.2.138
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:584: init(): [dns-client] attempts = 5
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:593: init(): [dns-client] timeout = 2000 ms
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:597: init(): [dns-client] ndots = 1
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:599: init(): [dns-client] search =
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:605: init(): [dns-client] badTtl = 1 s
2020/04/16 16:02:20 [debug] 21460#0: [lua] client.lua:607: init(): [dns-client] emptyTtl = 30 s
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: go-hello
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: correlation-id
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: pre-function
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: cors
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: ldap-auth
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: loggly
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: hmac-auth
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:209: loader_fn(): Loading custom plugin entity: 'hmac-auth.hmacauth_credentials'
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: zipkin
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: request-size-limiting
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: azure-functions
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: request-transformer
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: oauth2
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:209: loader_fn(): Loading custom plugin entity: 'oauth2.oauth2_credentials'
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:209: loader_fn(): Loading custom plugin entity: 'oauth2.oauth2_authorization_codes'
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:209: loader_fn(): Loading custom plugin entity: 'oauth2.oauth2_tokens'
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: response-transformer
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: ip-restriction
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: statsd
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: jwt
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:209: loader_fn(): Loading custom plugin entity: 'jwt.jwt_secrets'
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: proxy-cache
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: basic-auth
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:209: loader_fn(): Loading custom plugin entity: 'basic-auth.basicauth_credentials'
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: key-auth
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:209: loader_fn(): Loading custom plugin entity: 'key-auth.keyauth_credentials'
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: http-log
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: datadog
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: tcp-log
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: rate-limiting
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: post-function
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: prometheus
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: acl
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:209: loader_fn(): Loading custom plugin entity: 'acl.acls'
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: syslog
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: file-log
2020/04/16 16:02:20 [info] 21460#0: [lua] openssl.lua:5: using ffi, OpenSSL version linked: 1010106f
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: acme
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:209: loader_fn(): Loading custom plugin entity: 'acme.acme_storage'
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: udp-log
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: response-ratelimiting
2020/04/16 16:02:20 [debug] 21460#0: [kong] iam-ecs-credentials.lua:31 No ECS environment variables found for IAM
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: aws-lambda
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: session
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:209: loader_fn(): Loading custom plugin entity: 'session.sessions'
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: bot-detection
2020/04/16 16:02:20 [debug] 21460#0: [lua] plugins.lua:247: load_plugin(): Loading plugin: request-termination
2020/04/16 16:02:20 [notice] 21460#0: using the "epoll" event method
2020/04/16 16:02:20 [notice] 21460#0: openresty/1.15.8.3
2020/04/16 16:02:20 [notice] 21460#0: built by gcc 4.8.5 20150623 (Red Hat 4.8.5-39) (GCC)
2020/04/16 16:02:20 [notice] 21460#0: OS: Linux 5.6.2
2020/04/16 16:02:20 [notice] 21460#0: getrlimit(RLIMIT_NOFILE): 65535:65535
2020/04/16 16:02:20 [notice] 21477#0: start worker processes
2020/04/16 16:02:20 [notice] 21477#0: start worker process 21478
2020/04/16 16:02:20 [notice] 21477#0: start worker process 21479
2020/04/16 16:02:20 [notice] 21477#0: start worker process 21480
2020/04/16 16:02:20 [notice] 21477#0: start worker process 21481
2020/04/16 16:02:20 [debug] 21478#0: *1 [lua] globalpatches.lua:243: randomseed(): seeding PRNG from OpenSSL RAND_bytes()
2020/04/16 16:02:20 [debug] 21478#0: *1 [lua] globalpatches.lua:269: randomseed(): random seed: 581881119712 for worker nb 0
2020/04/16 16:02:20 [debug] 21479#0: *2 [lua] globalpatches.lua:243: randomseed(): seeding PRNG from OpenSSL RAND_bytes()
2020/04/16 16:02:20 [debug] 21479#0: *2 [lua] globalpatches.lua:269: randomseed(): random seed: 181771281069 for worker nb 1
2020/04/16 16:02:20 [debug] 21480#0: *3 [lua] globalpatches.lua:243: randomseed(): seeding PRNG from OpenSSL RAND_bytes()
2020/04/16 16:02:20 [debug] 21480#0: *3 [lua] globalpatches.lua:269: randomseed(): random seed: 502091091261 for worker nb 2
2020/04/16 16:02:20 [debug] 21478#0: *1 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=21478, data=nil
2020/04/16 16:02:20 [debug] 21479#0: *2 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=21479, data=nil
2020/04/16 16:02:20 [debug] 21481#0: *4 [lua] globalpatches.lua:243: randomseed(): seeding PRNG from OpenSSL RAND_bytes()
2020/04/16 16:02:20 [debug] 21481#0: *4 [lua] globalpatches.lua:269: randomseed(): random seed: 156194154212 for worker nb 3
2020/04/16 16:02:20 [debug] 21481#0: *4 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=21481, data=nil
2020/04/16 16:02:20 [debug] 21480#0: *3 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=21480, data=nil
2020/04/16 16:02:20 [debug] 21479#0: *2 [lua] counter.lua:50: new(): start timer for shdict kong on worker 1
2020/04/16 16:02:20 [info] 21479#0: 2 [kong] handler.lua:53 [acme] acme renew timer started on worker 1, context: init_worker_by_lua
2020/04/16 16:02:20 [debug] 21479#0: *2 [lua] counter.lua:50: new(): start timer for shdict prometheus_metrics on worker 1
2020/04/16 16:02:20 [debug] 21481#0: *4 [lua] counter.lua:50: new(): start timer for shdict kong on worker 3
2020/04/16 16:02:20 [info] 21481#0: 4 [kong] handler.lua:53 [acme] acme renew timer started on worker 3, context: init_worker_by_lua
2020/04/16 16:02:20 [notice] 21478#0: 1 [lua] cache_warmup.lua:46: cache_warmup_single_entity(): Preloading 'services' into the core_cache..., context: init_worker_by_lua
2020/04/16 16:02:20 [debug] 21480#0: *3 [lua] counter.lua:50: new(): start timer for shdict kong on worker 2
2020/04/16 16:02:20 [info] 21480#0: 3 [kong] handler.lua:53 [acme] acme renew timer started on worker 2, context: init_worker_by_lua
2020/04/16 16:02:20 [debug] 21481#0: *4 [lua] counter.lua:50: new(): start timer for shdict prometheus_metrics on worker 3
2020/04/16 16:02:20 [debug] 21480#0: *3 [lua] counter.lua:50: new(): start timer for shdict prometheus_metrics on worker 2
2020/04/16 16:02:20 [notice] 21478#0: 1 [lua] cache_warmup.lua:85: cache_warmup_single_entity(): finished preloading 'services' into the core_cache (in 64ms), context: init_worker_by_lua
2020/04/16 16:02:20 [notice] 21478#0: 1 [lua] cache_warmup.lua:46: cache_warmup_single_entity(): Preloading 'plugins' into the core_cache..., context: init_worker_by_lua
2020/04/16 16:02:20 [notice] 21478#0: 1 [lua] cache_warmup.lua:85: cache_warmup_single_entity(): finished preloading 'plugins' into the core_cache (in 8ms), context: init_worker_by_lua
2020/04/16 16:02:20 [debug] 21478#0: *1 [lua] counter.lua:50: new(): start timer for shdict kong on worker 0
2020/04/16 16:02:20 [info] 21478#0: 1 [kong] handler.lua:53 [acme] acme renew timer started on worker 0, context: init_worker_by_lua
2020/04/16 16:02:20 [debug] 21478#0: *1 [lua] counter.lua:50: new(): start timer for shdict prometheus_metrics on worker 0
2020/04/16 16:02:20 [debug] 21479#0: *5 [lua] balancer.lua:768: init(): initialized 0 balancer(s), 0 error(s)
2020/04/16 16:02:20 [debug] 21480#0: *7 [lua] balancer.lua:768: init(): initialized 0 balancer(s), 0 error(s)
2020/04/16 16:02:20 [debug] 21481#0: *8 [lua] balancer.lua:768: init(): initialized 0 balancer(s), 0 error(s)
2020/04/16 16:02:20 [notice] 21478#0: *9 [lua] cache_warmup.lua:25: warming up DNS entries ..., context: ngx.timer
2020/04/16 16:02:20 [debug] 21478#0: *10 [lua] balancer.lua:768: init(): initialized 0 balancer(s), 0 error(s)
2020/04/16 16:02:20 [notice] 21478#0: *11 [kong] go.lua:84 Starting go-pluginserver, context: ngx.timer
2020/04/16 16:02:20 [notice] 21478#0: *9 [lua] cache_warmup.lua:35: finished warming up DNS entries' into the cache (in 3ms), context: ngx.timer
2020/04/16 16:02:21 [debug] 21481#0: *22 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=21480, data=nil
2020/04/16 16:02:21 [debug] 21478#0: *23 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=21479, data=nil
2020/04/16 16:02:21 [debug] 21478#0: *23 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=21481, data=nil
2020/04/16 16:02:21 [debug] 21478#0: *23 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=21480, data=nil
2020/04/16 16:02:21 [debug] 21479#0: *27 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=21481, data=nil
2020/04/16 16:02:21 [debug] 21479#0: *27 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=resty-worker-events, event=started, pid=21480, data=nil

[az2az]

and I use go-hello plugin like this:

curl -i -X POST --url http://127.0.0.1:8001/services/ --data 'name=test-service' --data 'url=http://www.baidu.com'
curl -i -X POST --url http://127.0.0.1:8001/services/test-service/routes --data 'paths[]=/baidu'
curl -i -X POST --url http://127.0.0.1:8001/services/test-service/plugins/ --data 'name=go-hello'

[mfeledyn]

Good to know that the plugin is successfullly loaded. Could you try to install it globally ?
Also I recommend that you use a dedicated user for Kong processes, and setup go environment for this user.

[az2az]

hello,I install it as globally plugin,but it also can't work.my server have two ip address.the public address is 47.108.92.129,the private is 172.24.130.247.do I need some setup at dns in kong.conf?

[ealogar]

I think that this pr: Kong/kong#5586 and this Kong/kong#5597 fix indirectly this issue...

[gszr]

Thanks for linking the issues, @ealogar! Both PRs are merged by now, so closing this.