nginx worker stuck on shutdown after reload

[diefans]

Summary

On every reload there is one nginx worker stuck with

❯ ps ax| rg nginx
1363083 ?        Ss     0:00 nginx: master process /usr/local/openresty/nginx/sbin/nginx -p /usr/local/kong -c nginx.conf
1363298 ?        S      0:00 nginx: worker process is shutting down
1363780 ?        S      0:00 nginx: worker process
1363781 ?        S      0:00 nginx: worker process
1363782 ?        S      0:00 nginx: worker process
1363783 ?        S      0:00 nginx: worker process
1363784 ?        S      0:00 nginx: worker process
1363785 ?        S      0:00 nginx: worker process
1363786 ?        S      0:00 nginx: worker process
1363787 ?        S      0:00 nginx: worker process
1366486 pts/3    S+     0:00 rg nginx

❯ sudo strace -p 1363298
strace: Process 1363298 attached
write(4, "2021/03/09 08:13:47 [info] 30#0:"..., 82) = 82
epoll_pwait(11, [], 512, 234, NULL, 8)  = 0
read(22, 0x56041d03b380, 4096)          = -1 EAGAIN (Resource temporarily unavailable)
mprotect(0x7f4cbde30000, 65536, PROT_READ|PROT_WRITE) = 0
mprotect(0x7f4cbde30000, 65536, PROT_READ|PROT_EXEC) = 0
epoll_pwait(11, [], 512, 10000, NULL, 8) = 0
read(22, 0x56041d03b380, 4096)          = -1 EAGAIN (Resource temporarily unavailable)
epoll_pwait(11, [], 512, 10000, NULL, 8) = 0
read(22, 0x56041d03b380, 4096)          = -1 EAGAIN (Resource temporarily unavailable)
epoll_pwait(11, ^Cstrace: Process 1363298 detached
 <detached ...>

Steps To Reproduce

1. run kong with docker-compose start kong
2. run docker-compose exec kong kong reload

Additional Details & Logs

• Kong version (2.3.3)

• Kong error logs
  kong.log

• Operating system: archlinux

[diefans]

This is not happening with kong==2.2.2

[kikito]

Thank you for notifying us about this, we'll give it a look as soon as we can.

[kikito]

@diefans in order to replicate this accurately, it would be useful to know wether you are using a database or a dbless environment. Could you tell us that? A list of installed plugins might also be useful.

[diefans]

I use postgres.

Here is an excerpt of my docker-compose.yml:

  kong_db:
    image: postgres:9.6
    networks:
      - kong
    volumes:
      - kong_postgres:/var/lib/postgresql
    environment:
      POSTGRES_USER: kong
      POSTGRES_DB: kong
      POSTGRES_PASSWORD: kong

  kong:
    #image: kong:latest
    build: kong
    depends_on:
      - wait
      - kong_db
      - kong_bootstrap
      - jaeger
      - go-plugins
      - glu
      - backend
      - center
      - ucm
      - static
      - toolbox
    networks:
      - kong
    environment:
      KONG_DATABASE: postgres
      KONG_PG_HOST: kong_db
      KONG_PG_USER: kong
      KONG_PG_PASSWORD: kong
      KONG_CASSANDRA_CONTACT_POINTS: kong_db
      KONG_LOG_LEVEL: debug
      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_PROXY_LISTEN: 0.0.0.0:8080, 0.0.0.0:8443 ssl
      KONG_ADMIN_LISTEN: 0.0.0.0:8001, 0.0.0.0:8444 ssl
      KONG_PORT_MAP: "80:8080,443:8443"
      KONG_NGINX_PROXY_LARGE_CLIENT_HEADER_BUFFERS: 16 24k
      KONG_NGINX_PROXY_PROXY_BUFFER_SIZE: 128k
      KONG_NGINX_PROXY_PROXY_BUFFERS: 4 256k
      KONG_NGINX_PROXY_PROXY_BUSY_BUFFERS_SIZE: 256k
      KONG_NGINX_PROXY_INCLUDE: /etc/kong/nginx-session.conf
      KONG_NGINX_HTTP_INCLUDE: /etc/kong/extra_http.conf
      KONG_LUA_PACKAGE_PATH: /kong-bm-auth/?.lua;/kong-bm-auth/?/handler.lua;;

      KONG_GO_PLUGINS_DIR: /go-plugins
      KONG_GO_PLUGINSERVER_EXE: /usr/local/bin/go-pluginserver

      KONG_PLUGINSERVER_NAMES: go,python
      KONG_PLUGINSERVER_GO_SOCKET: /usr/local/kong/go_pluginserver.sock
      KONG_PLUGINSERVER_GO_START_CMD: >
        /usr/local/bin/go-pluginserver
        -kong-prefix /usr/local/kong/
        -plugins-directory /go-plugins
      KONG_PLUGINSERVER_GO_QUERY_CMD: >
        /usr/local/bin/go-pluginserver
        -dump-all-plugins
        -plugins-directory
        /go-plugins
      KONG_PLUGINS: ${KONG_PLUGINS-bundled, bm-auth, cors, bm-authx}
    volumes:
      - ${BM_AUTH_PATH}:/kong-bm-auth
      - ./kong/nginx-session.conf:/etc/kong/nginx-session.conf
      - ./kong/extra_http.conf:/etc/kong/extra_http.conf
      - go_plugins:/go-plugins
    extra_hosts: *bm_dns
    ports:
      - 80:8080
      - 443:8443
      - 8001:8001

[diefans]

If I comment out KONG_PLUGINSERVER_GO_... there is no worker stuck anymore on reload. So there must be something with running go-pluginserver itself, since I do not activate any go-plugins nor are there any requests made...

Interpreting the strace, I would guess something was terminated before something else was able to properly finish - thus waiting for something...

[diefans]

I created a minimal docker-compose setup to reproduce this behavior: https://github.com/diefans/kong-issue-6904

[diefans]

I don't know if this is used somewhere in production, but it would finally eat up resources and lead to some kind of DOS:

kong-test on  master
❯ docker-compose start kong
Starting kong ... done

kong-test on  master
❯ ps ax|rg nginx
 741377 ?        Ss     0:00 nginx: master process /usr/local/openresty/nginx/sbin/nginx -p /usr/local/kong -c nginx.conf
 741521 ?        S      0:00 nginx: worker process
 741522 ?        S      0:00 nginx: worker process
 741523 ?        S      0:00 nginx: worker process
 741524 ?        S      0:00 nginx: worker process
 741525 ?        S      0:00 nginx: worker process
 741526 ?        S      0:00 nginx: worker process
 741527 ?        S      0:00 nginx: worker process
 741528 ?        S      0:00 nginx: worker process
 741628 pts/9    S+     0:00 rg nginx

kong-test on  master
❯ docker-compose exec kong kong reload
Kong reloaded

kong-test on  master
❯ docker-compose exec kong kong reload
Kong reloaded

kong-test on  master
❯ docker-compose exec kong kong reload
Kong reloaded

kong-test on  master
❯ ps ax|rg nginx
 741377 ?        Ss     0:01 nginx: master process /usr/local/openresty/nginx/sbin/nginx -p /usr/local/kong -c nginx.conf
 741521 ?        S      0:00 nginx: worker process is shutting down
 742086 ?        S      0:00 nginx: worker process is shutting down
 742401 ?        S      0:00 nginx: worker process is shutting down
 742747 ?        S      0:00 nginx: worker process
 742748 ?        S      0:00 nginx: worker process
 742749 ?        S      0:00 nginx: worker process
 742750 ?        S      0:00 nginx: worker process
 742751 ?        S      0:00 nginx: worker process
 742752 ?        S      0:00 nginx: worker process
 742753 ?        S      0:00 nginx: worker process
 742754 ?        S      0:00 nginx: worker process
 742788 pts/9    S+     0:00 rg nginx

kong-test on  master
❯ ps ax| rg go-
 741529 ?        Sl     0:00 /go-plugins/go-pluginserver -kong-prefix /usr/local/kong/ -plugins-directory /go-plugins
 742094 ?        Sl     0:00 /go-plugins/go-pluginserver -kong-prefix /usr/local/kong/ -plugins-directory /go-plugins
 742410 ?        Sl     0:00 /go-plugins/go-pluginserver -kong-prefix /usr/local/kong/ -plugins-directory /go-plugins
 742755 ?        Sl     0:00 /go-plugins/go-pluginserver -kong-prefix /usr/local/kong/ -plugins-directory /go-plugins
 744756 pts/3    S+     0:00 rg go-