go-pluginserver terminated when using custom Go plugin

[PFadel]

Hello! I'm trying to use a custom Go plugin with my Kong, here are some details:

Kong Version: 2.0.2
Go Version: go version go1.13.5 linux/amd64
go-pluginserver version: Runtime Version: go1.13.5

I updated kong.conf to load my plugin, and Kong successfully starts. Although, when I execute a request to the service where my plugin is set, nothing happens, when I opend error.log i got a lot of this message:

2020/04/08 16:50:58 [notice] 26519#0: start worker process 26524
2020/04/08 16:50:58 [notice] 26519#0: start worker process 26525
2020/04/08 16:50:58 [notice] 26519#0: start worker process 26526
2020/04/08 16:50:58 [notice] 26519#0: start worker process 26527
2020/04/08 16:50:58 [notice] 26520#0: *1 [lua] cache_warmup.lua:45: cache_warmup_single_entity(): Preloading 'services' into the cache ..., context: init_worker_by_lua*
2020/04/08 16:50:58 [notice] 26520#0: *1 [lua] cache_warmup.lua:84: cache_warmup_single_entity(): finished preloading 'services' into the cache (in 85ms), context: init_worker_by_lua*
2020/04/08 16:50:58 [notice] 26520#0: *1 [lua] cache_warmup.lua:45: cache_warmup_single_entity(): Preloading 'plugins' into the cache ..., context: init_worker_by_lua*
2020/04/08 16:50:58 [notice] 26520#0: *1 [lua] cache_warmup.lua:84: cache_warmup_single_entity(): finished preloading 'plugins' into the cache (in 0ms), context: init_worker_by_lua*
2020/04/08 16:50:58 [notice] 26520#0: *16 [lua] cache_warmup.lua:25: warming up DNS entries ..., context: ngx.timer
2020/04/08 16:50:58 [notice] 26520#0: *16 [lua] cache_warmup.lua:35: finished warming up DNS entries' into the cache (in 6ms), context: ngx.timer
2020/04/08 16:51:24 [notice] 26519#0: signal 15 (SIGTERM) received from 27018, exiting
2020/04/08 16:51:24 [notice] 26520#0: exiting
2020/04/08 16:51:24 [notice] 26522#0: exiting
2020/04/08 16:51:24 [notice] 26521#0: exiting
2020/04/08 16:51:24 [notice] 26523#0: exiting
2020/04/08 16:51:24 [notice] 26524#0: exiting
2020/04/08 16:51:24 [notice] 26527#0: exiting
2020/04/08 16:51:24 [notice] 26525#0: exiting
2020/04/08 16:51:24 [notice] 26526#0: exiting
2020/04/08 16:51:24 [notice] 26527#0: exit
2020/04/08 16:51:24 [notice] 26520#0: exit
2020/04/08 16:51:24 [notice] 26521#0: exit
2020/04/08 16:51:24 [notice] 26522#0: exit
2020/04/08 16:51:24 [notice] 26519#0: signal 17 (SIGCHLD) received from 26527
2020/04/08 16:51:24 [notice] 26519#0: worker process 26520 exited with code 0
2020/04/08 16:51:24 [notice] 26519#0: worker process 26521 exited with code 0
2020/04/08 16:51:24 [notice] 26519#0: worker process 26522 exited with code 0
2020/04/08 16:51:24 [notice] 26519#0: worker process 26527 exited with code 0
2020/04/08 16:51:24 [notice] 26519#0: signal 29 (SIGIO) received
2020/04/08 16:51:24 [notice] 26523#0: exit
2020/04/08 16:51:24 [notice] 26519#0: signal 17 (SIGCHLD) received from 26523
2020/04/08 16:51:24 [notice] 26519#0: worker process 26523 exited with code 0
2020/04/08 16:51:24 [notice] 26519#0: signal 29 (SIGIO) received
2020/04/08 16:51:24 [notice] 26524#0: exit
2020/04/08 16:51:24 [notice] 26519#0: signal 17 (SIGCHLD) received from 26524
2020/04/08 16:51:24 [notice] 26519#0: worker process 26524 exited with code 0
2020/04/08 16:51:24 [notice] 26519#0: signal 29 (SIGIO) received
2020/04/08 16:51:24 [notice] 26526#0: exit
2020/04/08 16:51:24 [notice] 26519#0: signal 17 (SIGCHLD) received from 26526
2020/04/08 16:51:24 [notice] 26519#0: worker process 26526 exited with code 0
2020/04/08 16:51:24 [notice] 26519#0: signal 29 (SIGIO) received
2020/04/08 16:51:24 [notice] 26525#0: exit
2020/04/08 16:51:24 [notice] 26519#0: signal 17 (SIGCHLD) received from 26525
2020/04/08 16:51:24 [notice] 26519#0: worker process 26525 exited with code 0
2020/04/08 16:51:24 [notice] 26519#0: exit
2020/04/08 16:51:24 [notice] 27037#0: using the "epoll" event method
2020/04/08 16:51:24 [notice] 27037#0: openresty/1.15.8.2
2020/04/08 16:51:24 [notice] 27037#0: built by gcc 7.4.0 (Ubuntu 7.4.0-1ubuntu1~18.04.1) 
2020/04/08 16:51:24 [notice] 27037#0: OS: Linux 5.3.0-45-generic
2020/04/08 16:51:24 [notice] 27037#0: getrlimit(RLIMIT_NOFILE): 1024:4096
2020/04/08 16:51:24 [notice] 27049#0: start worker processes
2020/04/08 16:51:24 [notice] 27049#0: start worker process 27050
2020/04/08 16:51:24 [notice] 27049#0: start worker process 27051
2020/04/08 16:51:24 [notice] 27049#0: start worker process 27052
2020/04/08 16:51:24 [notice] 27049#0: start worker process 27053
2020/04/08 16:51:24 [notice] 27049#0: start worker process 27054
2020/04/08 16:51:24 [notice] 27049#0: start worker process 27055
2020/04/08 16:51:24 [notice] 27049#0: start worker process 27056
2020/04/08 16:51:24 [notice] 27049#0: start worker process 27057
2020/04/08 16:51:24 [warn] 27050#0: *1 [lua] globalpatches.lua:52: sleep(): executing a blocking 'sleep' (0.001 seconds), context: init_worker_by_lua*
2020/04/08 16:51:24 [notice] 27050#0: *1 [lua] cache_warmup.lua:45: cache_warmup_single_entity(): Preloading 'services' into the cache ..., context: init_worker_by_lua*
2020/04/08 16:51:24 [notice] 27050#0: *1 [lua] cache_warmup.lua:84: cache_warmup_single_entity(): finished preloading 'services' into the cache (in 102ms), context: init_worker_by_lua*
2020/04/08 16:51:24 [notice] 27050#0: *1 [lua] cache_warmup.lua:45: cache_warmup_single_entity(): Preloading 'plugins' into the cache ..., context: init_worker_by_lua*
2020/04/08 16:51:24 [notice] 27050#0: *1 [lua] cache_warmup.lua:84: cache_warmup_single_entity(): finished preloading 'plugins' into the cache (in 0ms), context: init_worker_by_lua*
2020/04/08 16:51:24 [notice] 27050#0: *17 [lua] cache_warmup.lua:25: warming up DNS entries ..., context: ngx.timer
2020/04/08 16:51:24 [notice] 27050#0: *19 [kong] go.lua:84 Starting go-pluginserver, context: ngx.timer
2020/04/08 16:51:24 [notice] 27050#0: signal 17 (SIGCHLD) received from 27142
2020/04/08 16:51:24 [notice] 27050#0: *19 [kong] go.lua:95 go-pluginserver terminated: exit 0, context: ngx.timer

And those last three lines go on forever:

2020/04/08 16:51:24 [notice] 27050#0: signal 17 (SIGCHLD) received from 27398
2020/04/08 16:51:24 [notice] 27050#0: *19 [kong] go.lua:95 go-pluginserver terminated: exit 0, context: ngx.timer
2020/04/08 16:51:24 [notice] 27050#0: *19 [kong] go.lua:84 Starting go-pluginserver, context: ngx.timer

Am I doing something wrong ? Any help would be appreciated.

[hhofchina]

me too

[az2az]

me too

[scguoi]

me too

[kuafou]

+1

[scguoi]

I resolved this problem by change nginx user in kong.conf. This user must have permission to exec go-pluginserver.

[sahibamatta]

tried changing the nginx user also in kong.conf. Still the same error. Also the user has permission to execute go-pluginserver.

[binhtd]

@sahibamatta

I installed kong direct on vm and kong configuration folder at /usr/local/kong/ i did the same with the comment above but i failed. I found that process running kong process and sub process that is nobody user. i tried to switch to user nobody and run process go-pluginserver but i still get the failure, i saw a message about permission go_pluginserver.sock -> i change the permission chown nobody /usr/local/kong after that go-pluginserrver that is running normally.

[gszr]

As pointed out, this is a permissioning issue (similar to point n. 2 here). The pluginserver needs to create a Unix domain socket in the Kong prefix; if it doesn't have permissions to do so (ie, its user ID differs from the Kong prefix owner), it will fail to start. Kong will try to restart the pluginserver, which continues failing to start, and this leads to the behavior described by the OP. Closing this, but feel free to reopen with more info if it doesn't work for you.

[diefans]

if it doesn't have permissions to do so (ie, its user ID differs from the Kong prefix owner), it will fail to start.

hard to find ...
log messages could be improved

[MatteoInfi]

Same bug here

[vnay92]

I spent a lot of time debugging this. Turned out that it was a panic in my code flow, which was causing it to exit and restart.

Also, turns out os.Getenv() doesn't retrieve the env values passed in the docker-compose's env. That's where my error was. Passing an ENV variablele and it wasn't being read, eventually causing log.Panicln().

My final debugging strategy end up writing log.Println() logs to a file, which was mounted on to the host and tailed.

PS: The plugin I wrote was based on the Embedded Server and not the go-pluginserver itself