Kong: Plugin tests hanging

Created on 6 Apr 2017 · 8Comments · Source: Kong/kong

TL;DR

Set KONG_NGINX_DAEMON=on.

Also, I managed to get a Docker dev environment working : https://github.com/MrSaints/docker-kong-dev

Summary

I'm trying to run some plugin tests in a Docker environment using make test-plugins, but for some reason, it keeps hanging. Nothing happens. The only thing I've identified in the logs are a constant stream of auto-joining:

2017/04/06 19:58:56 [debug] 64#64: *4 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:58:59 [debug] 64#64: *10 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:02 [debug] 64#64: *14 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:05 [debug] 64#64: *18 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:08 [debug] 64#64: *22 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:11 [debug] 64#64: *26 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:14 [debug] 64#64: *30 [lua] cluster.lua:20: log(): [cluster] auto-joining

I was wondering if there is someone who is familiar with the mechanics of Kong could help shed light on whether or not the above observation is actually problem. The tests doesn't seem to be running otherwise, so I'm wondering if it's being stuck at:

    assert(helpers.start_kong())
    client = helpers.proxy_client()

And if so, what could be the possible reasons behind it.

Steps To Reproduce

This is the Dockerfile I'm using: https://github.com/MrSaints/docker-kong-dev/blob/master/Dockerfile
I'm running make test-plugins with export BUSTED_ARGS="-o gtest -v --exclude-tags=ci"

It doesn't appear to be a database connectivity issue. There are no errors in Serf.

Additional Details & Logs

Kong version: 0.10.1
Kong debug-level startup logs: see below
Kong error logs: see above
Kong configuration: default
Operating System: Alpine 6.2.1

2017/04/06 19:58:53 [alert] 52#52: lua_code_cache is off; this will hurt performance in /kong/servroot/nginx-kong.conf:17
2017/04/06 19:58:53 [debug] 52#52: [lua] globalpatches.lua:9: installing the globalpatches
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:57: load_plugins(): Discovering used plugins
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: syslog
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: ldap-auth
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: rate-limiting
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: correlation-id
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: jwt
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: request-termination
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: runscope
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: request-transformer
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: http-log
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: loggly
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: response-transformer
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: basic-auth
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: tcp-log
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: hmac-auth
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: oauth2
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: acl
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: bot-detection
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: udp-log
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: cors
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: file-log
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: ip-restriction
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: datadog
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: request-size-limiting
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: galileo
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: aws-lambda
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: statsd
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: response-ratelimiting
2017/04/06 19:58:53 [debug] 52#52: [lua] kong.lua:83: load_plugins(): Loading plugin: key-auth
2017/04/06 19:58:53 [notice] 52#52: using the "epoll" event method
2017/04/06 19:58:53 [notice] 52#52: openresty/1.11.2.2
2017/04/06 19:58:53 [notice] 52#52: built by gcc 6.2.1 20160822 (Alpine 6.2.1) 
2017/04/06 19:58:53 [notice] 52#52: OS: Linux 4.9.13-moby
2017/04/06 19:58:53 [notice] 52#52: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2017/04/06 19:58:53 [notice] 52#52: start worker processes
2017/04/06 19:58:53 [notice] 52#52: start worker process 64
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] globalpatches.lua:217: randomseed(): seeding PRNG from OpenSSL RAND_bytes()
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] globalpatches.lua:243: randomseed(): random seed: 592093819787 for worker nb 0
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "bot-detection": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "cors": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "jwt": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "oauth2": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "key-auth": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "ldap-auth": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "basic-auth": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "hmac-auth": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "ip-restriction": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "request-size-limiting": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "acl": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "rate-limiting": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "response-ratelimiting": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "request-transformer": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "response-transformer": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "aws-lambda": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "http-log": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "statsd": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "datadog": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "file-log": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "udp-log": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "request-termination": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "loggly": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "runscope": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "syslog": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "galileo": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "tcp-log": init_worker
2017/04/06 19:58:53 [debug] 64#64: *1 [lua] base_plugin.lua:9: init_worker():  executing plugin "correlation-id": init_worker
2017/04/06 19:58:56 [debug] 64#64: *4 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:58:59 [debug] 64#64: *10 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:02 [debug] 64#64: *14 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:05 [debug] 64#64: *18 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:08 [debug] 64#64: *22 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:11 [debug] 64#64: *26 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:14 [debug] 64#64: *30 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:17 [debug] 64#64: *34 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:20 [debug] 64#64: *38 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:23 [debug] 64#64: *42 [lua] cluster.lua:20: log(): [cluster] sending keepalive event to datastore
2017/04/06 19:59:23 [debug] 64#64: *43 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:26 [debug] 64#64: *47 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:29 [debug] 64#64: *51 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:32 [debug] 64#64: *55 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:35 [debug] 64#64: *59 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:38 [debug] 64#64: *63 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:41 [debug] 64#64: *67 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:44 [debug] 64#64: *71 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:47 [debug] 64#64: *75 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:50 [debug] 64#64: *79 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 19:59:53 [debug] 64#64: *83 [lua] cluster.lua:20: log(): [cluster] sending keepalive event to datastore
2017/04/06 19:59:53 [debug] 64#64: *86 [lua] cluster.lua:20: log(): [cluster] auto-joining
2017/04/06 20:00:23 [debug] 64#64: *116 [lua] cluster.lua:20: log(): [cluster] sending keepalive event to datastore
2017/04/06 20:00:53 [debug] 64#64: *148 [lua] cluster.lua:20: log(): [cluster] sending keepalive event to datastore
2017/04/06 20:01:23 [debug] 64#64: *180 [lua] cluster.lua:20: log(): [cluster] sending keepalive event to datastore
2017/04/06 20:01:53 [debug] 64#64: *211 [lua] cluster.lua:20: log(): [cluster] sending keepalive event to datastore

Source

MrSaints

All 8 comments

Well, I guess I solved my own problem. I had set KONG_NGINX_DAEMON=off.

Tests should always be executed using KONG_NGINX_DAEMON=on, otherwise exec(..) will just be holding on in foreground rather than background.

MrSaints on 7 Apr 2017

this is probably specific to the Docker environment, it might shutdown the container is the foreground process exits

Tieske on 7 Apr 2017

Yes, and no @Tieske.

I had intentionally set KONG_NGINX_DAEMON=off so that the container won't exit. And that led to the problem I had where the tests would hang because they aren't running in background, so the exec(..) method in the helper never returns. This will probably happen regardless of whether it is executed in Docker.

Once I removed it, the tests ran correctly. Also, I recall you mentioned that both database drivers (Cassandra, and Postgresql) are required to run plugin tests. This is not the case. It actually works fine with just one 😄

I now have a functional Docker dev environment for Kong: https://github.com/mrsaints/docker-kong-dev

MrSaints on 7 Apr 2017

Once I removed it, the tests ran correctly. Also, I recall you mentioned that both database drivers (Cassandra, and Postgresql) are required to run plugin tests. This is not the case. It actually works fine with just one 😄

No. Then you did not run the full test suite, several tests are executed against both databases.

Tieske on 7 Apr 2017

👍1

With all due respect, I did say "plugin tests", not full test suite.

MrSaints on 7 Apr 2017

My bad!

You're just running your own plugin tests?

Tieske on 7 Apr 2017

👍1

@Tieske No worries.

Yep 😄 I was hoping to get body logging working for one of the logging plugins. I know it's probably not a great idea to log bodies (at least several comments), but we need to capture the payload, and it's small in most cases.

Thanks for your work on Kong! It's great.

MrSaints on 7 Apr 2017

OH MAN, thank you so much @MrSaints. I spent two whole days wrestling with this and couldn't figure it out.