search

Kong / kong

🦍 The Cloud-Native API Gateway and AI Gateway.
https://konghq.com/install/#kong-community
Apache License 2.0
39.24k stars 4.81k forks source link

Kong blocking requests #3082

Closed grillorafael closed 6 years ago

grillorafael commented 6 years ago

Summary

Hey guys,

I was using kong for some tiny APIs we have in the office here but ever since I added one of the heavy ones (Some requests take a minute) to it, it seems that some of the kong instances just block and stop responding.

I end up restarting kong and then things comes back to normal. If I access the underneath API directly, things work without a problem.

Additional Details & Logs

Some issues on the logs:

2017/12/08 17:51:17 [error] 53#0: *20074 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET <REDACTED> HTTP/1.1", upstream: "http://11.211.103.77:9000/<REDACTED>", host: "<REDACTED>"
2017/12/08 17:51:17 [error] 53#0: *20074 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for <INTERNAL_NAME_REDACTED>' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /<REDACTED> HTTP/1.1", upstream: "http://11.211.103.77:9000/<REDACTED>", host: "<REDACTED>"
2017/12/08 17:51:17 [error] 53#0: *20074 failed to run balancer_by_lua*: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua*
stack traceback:
    [C]: in function 'say'
    /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer'
    balancer_by_lua:2: in function <balancer_by_lua:1> while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /<REDACTED> HTTP/1.1", upstream: "http://11.211.103.77:9000/<REDACTED>", host: "<REDACTED>"
2017/12/08 17:11:34 [warn] 54#0: *2 [lua] globalpatches.lua:68: sleep(): executing a blocking 'sleep' (0.001 seconds), context: init_worker_by_lua*
2017/12/08 17:11:34 [warn] 55#0: *3 [lua] globalpatches.lua:68: sleep(): executing a blocking 'sleep' (0.001 seconds), context: init_worker_by_lua*
2017/12/08 17:11:34 [warn] 53#0: *1 [lua] globalpatches.lua:68: sleep(): executing a blocking 'sleep' (0.001 seconds), context: init_worker_by_lua*
2017/12/08 17:11:34 [warn] 54#0: *2 [lua] globalpatches.lua:68: sleep(): executing a blocking 'sleep' (0.002 seconds), context: init_worker_by_lua*
2017/12/08 17:11:34 [warn] 55#0: *3 [lua] globalpatches.lua:68: sleep(): executing a blocking 'sleep' (0.002 seconds), context: init_worker_by_lua*
2017/12/08 17:11:34 [warn] 55#0: *3 [lua] globalpatches.lua:68: sleep(): executing a blocking 'sleep' (0.004 seconds), context: init_worker_by_lua*

EDIT:

Each instance have 4 cpu shares and 4gb of ram and I have 4 instances running

hishamhm commented 6 years ago

dns server error: 4 server failure -- this in particular looks like a DNS configuration issue is involved. But still, Kong instances shouldn't lock up. A more complete log listing rather than selected lines may give us a better insight on what is going on.

grillorafael commented 6 years ago

those are the only things in the error logs. Anything else I can do tho get more logs? (Apart from the startup -vv)

p0pr0ck5 commented 6 years ago

You mentioned some requests take a minute. Have you tried adjusting the timeout values in the API definitions to longer than the default (60s)?

grillorafael commented 6 years ago

The request timeout is 90s, upstream connect is 6 seconds.

On Fri 8 Dec 2017 at 20:54, Robert notifications@github.com wrote:

You mentioned some requests take a minute. Have you tried adjusting the timeout values in the API definitions to longer than the default (60s)?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/Kong/kong/issues/3082#issuecomment-350369380, or mute the thread https://github.com/notifications/unsubscribe-auth/ABunK6xNoYCHOKwSwl8gA5RJfX585Y8-ks5s-aIEgaJpZM4Q7cpy .

-- Rafael Grillo Abreu +353 083 8044675 LinkedIn https://www.linkedin.com/profile/view?id=89764578 Developer

grillorafael commented 6 years ago

But even with a very high timeout I believe it shouldn't make my kong instance stop responding to other requests, right?

Tieske commented 6 years ago

the warning in the log regarding 'blocking sleep' are harmless. This is during initializiation in init_worker phase, in which the regular ngx.sleep() function is unavailable.

Tieske commented 6 years ago

so what is happening here:

2017/12/08 17:51:17 [error] 53#0: *20074 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET

HTTP/1.1", upstream: "http://11.211.103.77:9000/", host: " "

You are doing a get request, and the receive fails. As @p0pr0ck5 suggested, my initial thought here also goes to a timeout. So check the timeout settings on the api object you created. To be sure can you show us the configuration?

2017/12/08 17:51:17 [error] 53#0: *20074 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for ' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET / HTTP/1.1", upstream: "http://11.211.103.77:9000/", host: "

"

Because of the failure (and the request being a GET request, which is idempotent) nginx will do a retry. But apparently the hostname's ttl expired and the dns resolver has to do a new lookup. Unfortunately because the retry run in the balancer_by_lua context no sockets are available to comply with that request. Hence the dns resolver will internally create the "4 server failure" error. Noticed by its description "cache only lookup failed". Because of the limited context, no sockets are available and the resolver tries a "cache only lookup", which fails because the ttl apparently expired, and due to the length of the request, the dns_stale_ttl (default 4 seconds) has also expired.

2017/12/08 17:51:17 [error] 53#0: 20074 failed to run balancer_by_lua: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua* stack traceback: [C]: in function 'say' /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer' balancer_by_lua:2: in function while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET / HTTP/1.1", upstream: "http://11.211.103.77:9000/", host: ""

And here an error is thrown. Because the dns resolution failed and error is returned and when handling that a 500 is returned at (most likely) this line: https://github.com/Kong/kong/blob/master/kong/init.lua#L297 But... the responses module uses the say method, which is (just like the sockets) not available in the balancer_by_lua context (it appears). Since the request is not terminated because of the Lua error, it probably retries on the previously set ip address, and then times out again, and it all starts over...

So there is a bug, in that Kong cannot use say in the limited balancer_by_lua context (a bug which probably exists in multiple places)

But to resolve @grillorafael s problem:

  1. can you provide the API definition
  2. what dns records do you have for your upstream_url host name? (cname/a/SRV, please list them all)
  3. if using a balancer (upstream entity in Kong) please provide the configuration and the configured targets.
grillorafael commented 6 years ago

Hey everyone, thanks for the quick response.

As for 3, we are not using Kong balancer. We are pointing to this DNS address which is the default dcos load balancer.

API definition:

{
    "created_at": 1511450161000,
    "strip_uri": true,
    "id": "cc924892-9914-46e8-b2e8-7304ecd8ff6f",
    "hosts": ["<redacted>"],
    "name": "EventsDashboard",
    "http_if_terminated": false,
    "https_only": false,
    "retries": 5,
    "preserve_host": true,
    "upstream_connect_timeout": 6000,
    "upstream_read_timeout": 900000,
    "upstream_send_timeout": 6000,
    "upstream_url": "http://figsworkbench-dashboard:9000"
}

I'll add the DNS details tomorrow morning

Tieske commented 6 years ago

That timeout is 900000, so more than the 90s, 900s actually.

Can you reduce that to 90000, and then try again (leaving it running for at least, say 10 minutes? and collect the logs. so we can see whether they are actually retries and how Kong behaves exactly

grillorafael commented 6 years ago

I'll give it a try and I'll let you know.

One thing I notice is that it seems to work better when I have only one instance running.

grillorafael commented 6 years ago

I did change to 90000 but I see the same thing in the logs.

2017/12/09 11:43:35 [error] 53#0: *1754336 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9220952&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9220952&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 53#0: *1754312 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9644196&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9644196&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 53#0: *1754769 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9733296&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9733296&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 53#0: *1754327 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9229350&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9229350&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 53#0: *1754318 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9550163&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9550163&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 53#0: *1754304 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9168635&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9168635&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 53#0: *1754354 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9347932&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9347932&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 53#0: *1755281 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9566459&eventTypes=destination&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9566459&eventTypes=destination&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754150 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9329837&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9329837&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 53#0: *1754782 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=8912297&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=8912297&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 54#0: *1754614 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?page=0&imos=9515644&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?page=0&imos=9515644&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 53#0: *1754797 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9185774&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit&order=asc&pageSize=10000&page=0 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9185774&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit&order=asc&pageSize=10000&page=0", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755760 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9358371&eventTypes=destination&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9358371&eventTypes=destination&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754150 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for figsworkbench-dashboard' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9329837&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9329837&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755769 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754150 failed to run balancer_by_lua*: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua*
stack traceback:
    [C]: in function 'say'
    /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer'
    balancer_by_lua:2: in function <balancer_by_lua:1> while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9329837&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9329837&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755756 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755769 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 54#0: *1754614 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for figsworkbench-dashboard' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?page=0&imos=9515644&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?page=0&imos=9515644&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754147 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9050278&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9050278&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755756 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755769 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755756 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 54#0: *1754614 failed to run balancer_by_lua*: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua*
stack traceback:
    [C]: in function 'say'
    /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer'
    balancer_by_lua:2: in function <balancer_by_lua:1> while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?page=0&imos=9515644&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?page=0&imos=9515644&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755769 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755756 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755769 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755756 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755769 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755756 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755769 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?pageSize=100&imos=9490557&page=0", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754147 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for figsworkbench-dashboard' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9050278&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9050278&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754147 failed to run balancer_by_lua*: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua*
stack traceback:
    [C]: in function 'say'
    /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer'
    balancer_by_lua:2: in function <balancer_by_lua:1> while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9050278&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9050278&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755756 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?imos=9698226&page=0&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755762 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?imos=7642510&page=0&pageSize=100 HTTP/1.1", upstream: "httpvents.commodityvectors.com"
2017/12/09 11:43:35 [error] 53#0: *1754641 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?imos=9176773&page=0&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?imos=9176773&page=0&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755782 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?page=0&imos=9426714&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?page=0&imos=9426714&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754144 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9370977&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9370977&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755745 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?page=0&imos=9644251&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?page=0&imos=9644251&pageSize=100", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755737 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?pageSize=100&page=0&imos=9136917 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?pageSize=100&page=0&imos=9136917", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754144 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for figsworkbench-dashboard' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9370977&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9370977&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754144 failed to run balancer_by_lua*: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua*
stack traceback:
    [C]: in function 'say'
    /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer'
    balancer_by_lua:2: in function <balancer_by_lua:1> while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9370977&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9370977&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 59#0: *1755757 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9271951&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9271951&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 54#0: *1754487 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for figsworkbench-dashboard' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9494151&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9494151&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754148 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9743291&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9743291&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 54#0: *1754487 failed to run balancer_by_lua*: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua*
stack traceback:
    [C]: in function 'say'
    /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer'
    balancer_by_lua:2: in function <balancer_by_lua:1> while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9494151&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9494151&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754148 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for figsworkbench-dashboard' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9743291&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9743291&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754148 failed to run balancer_by_lua*: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua*
stack traceback:
    [C]: in function 'say'
    /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer'
    balancer_by_lua:2: in function <balancer_by_lua:1> while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9743291&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9743291&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754146 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9423786&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9423786&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754146 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for figsworkbench-dashboard' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9423786&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9423786&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754146 failed to run balancer_by_lua*: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua*
stack traceback:
    [C]: in function 'say'
    /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer'
    balancer_by_lua:2: in function <balancer_by_lua:1> while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9423786&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9423786&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754149 upstream prematurely closed connection while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9591038&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9591038&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754149 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for figsworkbench-dashboard' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9591038&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9591038&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"
2017/12/09 11:43:35 [error] 57#0: *1754149 failed to run balancer_by_lua*: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua*
stack traceback:
    [C]: in function 'say'
    /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer'
    balancer_by_lua:2: in function <balancer_by_lua:1> while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9591038&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9591038&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<REDACTED>"

Interesting is that it all happened at the same time and they are all different requests

hishamhm commented 6 years ago

But... the responses module uses the say method, which is (just like the sockets) not available in the balancer_by_lua context (it appears).

@Tieske I caught that bug when I was worked on health checks and added a workaround for that context limitation. So a fix for this will be arriving in the next major release.

Tieske commented 6 years ago

ok, so that are a LOT of errors. Looks to me you are having some infra issues?

So how is the dns configured? to be sure, can you include the relevant resolv.conf and hosts files?

grillorafael commented 6 years ago

resolve.conf

# Generated by gen_resolvconf.py. Do not edit.
# Change configuration options by changing DC/OS cluster configuration.
# This file must be overwritten regularly for proper cluster operation around
# master failure.

options timeout:1
options attempts:3

search marathon.l4lb.thisdcos.directory l4lb.thisdcos.directory marathon.mesos cv.vpc
nameserver 198.51.100.1
nameserver 198.51.100.2
nameserver 198.51.100.3

hosts

127.0.0.1   localhost
::1 localhost ip6-localhost ip6-loopback
fe00::0 ip6-localnet
ff00::0 ip6-mcastprefix
ff02::1 ip6-allnodes
ff02::2 ip6-allrouters
172.17.0.2  f77e2b6d5aad

Where the nameservers are dc/os resolvers.

Tieske commented 6 years ago

any idea what is causing all those premature errors? are those all for failing requests to the one api you have that takes a minute to respond?

and if you set log_level=debug in the configuration file, does it show more info? (you can also set enviornment variable KONG_LOG_LEVEL=debug)

grillorafael commented 6 years ago

I'll turn it on now and I'll post here.

Tieske commented 6 years ago

Just trying to think out loud here...

Hosts and resolv.conf look normal to me. No ndots is given, so regular default would be 1 for that. Default Kong search order is: dns_order=LAST,SRV,A,CNAME

So dns search order will be;

You don't have environment variables LOCALDOMAIN and RES_OPTIONS set do you?

Tieske commented 6 years ago

What do your dns records look like? Eg. what is the output of dig figsworkbench-dashboard SRV? (please also for A and CNAME)

Tieske commented 6 years ago

Also, when you start hitting Kong with those requests, how much time goes by before the errors appear? the error "dns server error: 4 server failure, cache only lookup failed while connecting to upstream" I mean

grillorafael commented 6 years ago

I also tried changing DNS order once (removing srv from it).

This is what I have for dns order now: LAST,A,CNAME

2017/12/11 16:31:51 [info] 60#0: *241452 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 10.250.3.2, server: kong, request: "GET /api/vessels/lastLiveVesselTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/vessels/lastLiveVesselTime", host: "<REDACTED>"
2017/12/11 16:31:51 [debug] 60#0: *241452 [lua] base_plugin.lua:36: log(): executing plugin "statsd": log
2017/12/11 16:31:51 [info] 60#0: *241447 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:31:51 [debug] 60#0: *241447 [lua] base_plugin.lua:36: log(): executing plugin "statsd": log
2017/12/11 16:31:51 [debug] 60#0: *242099 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.count:1|c
2017/12/11 16:31:51 [debug] 60#0: *242099 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.latency:59502|ms
2017/12/11 16:31:51 [debug] 60#0: *242099 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.size:239|ms
2017/12/11 16:31:51 [debug] 60#0: *242099 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.499:1|c
2017/12/11 16:31:51 [debug] 60#0: *242099 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.total:1|c
2017/12/11 16:31:51 [debug] 60#0: *242099 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.response.size:0|ms
2017/12/11 16:31:51 [debug] 60#0: *242099 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.upstream_latency:-1|ms
2017/12/11 16:31:51 [debug] 60#0: *242099 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.kong_latency:0|ms
2017/12/11 16:31:51 [debug] 60#0: *242104 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.count:1|c
2017/12/11 16:31:51 [debug] 60#0: *242104 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.latency:59505|ms
2017/12/11 16:31:51 [debug] 60#0: *242104 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.size:233|ms
2017/12/11 16:31:51 [debug] 60#0: *242104 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.499:1|c
2017/12/11 16:31:51 [debug] 60#0: *242104 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.total:1|c
2017/12/11 16:31:51 [debug] 60#0: *242104 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.response.size:0|ms
2017/12/11 16:31:51 [debug] 60#0: *242104 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.upstream_latency:-1|ms
2017/12/11 16:31:51 [debug] 60#0: *242104 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.kong_latency:2|ms
2017/12/11 16:31:51 [debug] 59#0: *242107 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009911.231
2017/12/11 16:31:51 [debug] 60#0: *242119 [lua] base_plugin.lua:20: rewrite(): executing plugin "statsd": rewrite
2017/12/11 16:31:51 [debug] 60#0: *242119 [lua] base_plugin.lua:24: access(): executing plugin "statsd": access
2017/12/11 16:31:51 [debug] 60#0: *242124 [lua] base_plugin.lua:20: rewrite(): executing plugin "statsd": rewrite
2017/12/11 16:31:51 [debug] 60#0: *242124 [lua] base_plugin.lua:24: access(): executing plugin "statsd": access
2017/12/11 16:31:56 [debug] 57#0: *242204 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009916.233
2017/12/11 16:32:01 [debug] 58#0: *242252 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009921.233
2017/12/11 16:32:06 [debug] 59#0: *242304 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009926.233
2017/12/11 16:32:11 [debug] 56#0: *242356 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009931.233
2017/12/11 16:32:16 [debug] 58#0: *242408 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009936.235
2017/12/11 16:32:21 [debug] 57#0: *242460 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009941.235
2017/12/11 16:32:26 [debug] 55#0: *242512 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009946.235
2017/12/11 16:32:31 [debug] 53#0: *242564 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009951.235
2017/12/11 16:32:36 [debug] 60#0: *242616 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009956.236
2017/12/11 16:32:41 [debug] 56#0: *242668 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009961.236
2017/12/11 16:32:46 [debug] 60#0: *242720 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009966.238
2017/12/11 16:32:49 [info] 56#0: *242756 client closed connection while SSL handshaking, client: 10.250.3.3, server: 0.0.0.0:8444
2017/12/11 16:32:51 [info] 60#0: *242119 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 10.250.3.2, server: kong, request: "GET /api/vessels/lastLiveVesselTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/vessels/lastLiveVesselTime", host: "<REDACTED>"
2017/12/11 16:32:51 [debug] 60#0: *242119 [lua] base_plugin.lua:36: log(): executing plugin "statsd": log
2017/12/11 16:32:51 [info] 60#0: *242124 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:32:51 [debug] 60#0: *242124 [lua] base_plugin.lua:36: log(): executing plugin "statsd": log
2017/12/11 16:32:51 [debug] 60#0: *242773 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.count:1|c
2017/12/11 16:32:51 [debug] 60#0: *242773 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.latency:59510|ms
2017/12/11 16:32:51 [debug] 60#0: *242773 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.size:239|ms
2017/12/11 16:32:51 [debug] 60#0: *242773 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.499:1|c
2017/12/11 16:32:51 [debug] 60#0: *242773 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.total:1|c
2017/12/11 16:32:51 [debug] 60#0: *242773 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.response.size:0|ms
2017/12/11 16:32:51 [debug] 60#0: *242773 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.upstream_latency:-1|ms
2017/12/11 16:32:51 [debug] 60#0: *242773 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.kong_latency:1|ms
2017/12/11 16:32:51 [debug] 60#0: *242778 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.count:1|c
2017/12/11 16:32:51 [debug] 60#0: *242778 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.latency:59510|ms
2017/12/11 16:32:51 [debug] 60#0: *242778 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.size:233|ms
2017/12/11 16:32:51 [debug] 60#0: *242778 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.499:1|c
2017/12/11 16:32:51 [debug] 60#0: *242778 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.total:1|c
2017/12/11 16:32:51 [debug] 60#0: *242778 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.response.size:0|ms
2017/12/11 16:32:51 [debug] 60#0: *242778 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.upstream_latency:-1|ms
2017/12/11 16:32:51 [debug] 60#0: *242778 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.kong_latency:0|ms
2017/12/11 16:32:51 [debug] 57#0: *242781 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009971.238
2017/12/11 16:32:56 [debug] 55#0: *242870 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009976.239
2017/12/11 16:33:01 [debug] 53#0: *242918 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009981.239
2017/12/11 16:33:01 [debug] 53#0: *242930 [lua] base_plugin.lua:20: rewrite(): executing plugin "statsd": rewrite
2017/12/11 16:33:01 [debug] 53#0: *242930 [lua] base_plugin.lua:24: access(): executing plugin "statsd": access
2017/12/11 16:33:01 [debug] 53#0: *242935 [lua] base_plugin.lua:20: rewrite(): executing plugin "statsd": rewrite
2017/12/11 16:33:01 [debug] 53#0: *242935 [lua] base_plugin.lua:24: access(): executing plugin "statsd": access
2017/12/11 16:33:06 [debug] 59#0: *242976 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009986.24
2017/12/11 16:33:11 [debug] 56#0: *243028 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009991.24
2017/12/11 16:33:16 [debug] 53#0: *243080 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513009996.24
2017/12/11 16:33:21 [debug] 60#0: *243132 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010001.241
2017/12/11 16:33:25 [debug] 59#0: *243176 [lua] base_plugin.lua:20: rewrite(): executing plugin "statsd": rewrite
2017/12/11 16:33:25 [debug] 59#0: *243176 [lua] base_plugin.lua:24: access(): executing plugin "statsd": access
2017/12/11 16:33:26 [debug] 54#0: *243189 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010006.241
2017/12/11 16:33:31 [debug] 56#0: *243241 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010011.242
2017/12/11 16:33:36 [debug] 57#0: *243293 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010016.243
2017/12/11 16:33:41 [debug] 55#0: *243345 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010021.243
2017/12/11 16:33:46 [debug] 53#0: *243397 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010026.243
2017/12/11 16:33:49 [info] 59#0: *243433 client closed connection while SSL handshaking, client: 10.250.3.3, server: 0.0.0.0:8444
2017/12/11 16:33:51 [debug] 60#0: *243450 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010031.244
2017/12/11 16:33:56 [debug] 57#0: *243539 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010036.244
2017/12/11 16:34:01 [info] 53#0: *242930 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 10.250.3.2, server: kong, request: "GET /api/vessels/lastLiveVesselTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/vessels/lastLiveVesselTime", host: "<REDACTED>"
2017/12/11 16:34:01 [debug] 53#0: *242930 [lua] base_plugin.lua:36: log(): executing plugin "statsd": log
2017/12/11 16:34:01 [info] 53#0: *242935 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:34:01 [debug] 53#0: *242935 [lua] base_plugin.lua:36: log(): executing plugin "statsd": log
2017/12/11 16:34:01 [debug] 53#0: *243586 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.count:1|c
2017/12/11 16:34:01 [debug] 53#0: *243586 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.latency:59496|ms
2017/12/11 16:34:01 [debug] 53#0: *243586 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.size:239|ms
2017/12/11 16:34:01 [debug] 53#0: *243586 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.499:1|c
2017/12/11 16:34:01 [debug] 53#0: *243586 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.total:1|c
2017/12/11 16:34:01 [debug] 53#0: *243586 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.response.size:0|ms
2017/12/11 16:34:01 [debug] 53#0: *243586 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.upstream_latency:-1|ms
2017/12/11 16:34:01 [debug] 53#0: *243586 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.kong_latency:2|ms
2017/12/11 16:34:01 [debug] 53#0: *243591 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.count:1|c
2017/12/11 16:34:01 [debug] 53#0: *243591 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.latency:59491|ms
2017/12/11 16:34:01 [debug] 53#0: *243591 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.size:233|ms
2017/12/11 16:34:01 [debug] 53#0: *243591 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.499:1|c
2017/12/11 16:34:01 [debug] 53#0: *243591 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.total:1|c
2017/12/11 16:34:01 [debug] 53#0: *243591 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.response.size:0|ms
2017/12/11 16:34:01 [debug] 53#0: *243591 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.upstream_latency:-1|ms
2017/12/11 16:34:01 [debug] 53#0: *243591 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.kong_latency:0|ms
2017/12/11 16:34:01 [debug] 57#0: *243596 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010041.246
2017/12/11 16:34:01 [debug] 55#0: *243607 [lua] base_plugin.lua:20: rewrite(): executing plugin "statsd": rewrite
2017/12/11 16:34:01 [debug] 55#0: *243607 [lua] base_plugin.lua:24: access(): executing plugin "statsd": access
2017/12/11 16:34:01 [debug] 55#0: *243612 [lua] base_plugin.lua:20: rewrite(): executing plugin "statsd": rewrite
2017/12/11 16:34:01 [debug] 55#0: *243612 [lua] base_plugin.lua:24: access(): executing plugin "statsd": access
2017/12/11 16:34:06 [debug] 60#0: *243653 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010046.246
2017/12/11 16:34:11 [debug] 54#0: *243705 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010051.246
2017/12/11 16:34:16 [debug] 59#0: *243757 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010056.246
2017/12/11 16:34:21 [debug] 58#0: *243809 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010061.247
2017/12/11 16:34:26 [debug] 57#0: *243862 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010066.248
2017/12/11 16:34:31 [debug] 56#0: *243913 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010071.248
2017/12/11 16:34:36 [debug] 59#0: *243965 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010076.25
2017/12/11 16:34:41 [debug] 58#0: *244017 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010081.25
2017/12/11 16:34:46 [debug] 60#0: *244069 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010086.25
2017/12/11 16:34:49 [info] 55#0: *244105 client closed connection while SSL handshaking, client: 10.250.3.3, server: 0.0.0.0:8444
2017/12/11 16:34:51 [debug] 56#0: *244122 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010091.25
2017/12/11 16:34:53 [error] 55#0: *243612 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/vessels/lastLiveVesselTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/vessels/lastLiveVesselTime", host: "<REDACTED>"
2017/12/11 16:34:53 [error] 55#0: *243612 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for figsworkbench-dashboard' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/vessels/lastLiveVesselTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/vessels/lastLiveVesselTime", host: "<REDACTED>"
2017/12/11 16:34:53 [error] 55#0: *243612 failed to run balancer_by_lua*: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua*
stack traceback:
    [C]: in function 'say'
    /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer'
    balancer_by_lua:2: in function <balancer_by_lua:1> while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/vessels/lastLiveVesselTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/vessels/lastLiveVesselTime", host: "<REDACTED>"
2017/12/11 16:34:55 [error] 59#0: *243176 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:34:55 [error] 59#0: *243176 [lua] init.lua:294: balancer(): failed to retry the dns/balancer resolver for figsworkbench-dashboard' with: dns server error: 4 server failure, cache only lookup failed while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:34:55 [error] 59#0: *243176 failed to run balancer_by_lua*: /usr/local/share/lua/5.1/kong/tools/responses.lua:133: API disabled in the context of balancer_by_lua*
stack traceback:
    [C]: in function 'say'
    /usr/local/share/lua/5.1/kong/tools/responses.lua:133: in function 'balancer'
    balancer_by_lua:2: in function <balancer_by_lua:1> while connecting to upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:34:56 [debug] 53#0: *244212 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010096.25
2017/12/11 16:35:01 [info] 55#0: *243607 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:01 [debug] 55#0: *243607 [lua] base_plugin.lua:36: log(): executing plugin "statsd": log
2017/12/11 16:35:01 [debug] 55#0: *244260 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.count:1|c
2017/12/11 16:35:01 [debug] 55#0: *244260 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.latency:59479|ms
2017/12/11 16:35:01 [debug] 55#0: *244260 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.size:233|ms
2017/12/11 16:35:01 [debug] 55#0: *244260 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.499:1|c
2017/12/11 16:35:01 [debug] 55#0: *244260 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.total:1|c
2017/12/11 16:35:01 [debug] 55#0: *244260 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.response.size:0|ms
2017/12/11 16:35:01 [debug] 55#0: *244260 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.upstream_latency:-1|ms
2017/12/11 16:35:01 [debug] 55#0: *244260 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.kong_latency:2|ms
2017/12/11 16:35:01 [debug] 53#0: *244266 [lua] cluster_events.lua:231: [cluster_events] polling events from: 1513007936.056 to: 1513010101.251
2017/12/11 16:35:02 [debug] 59#0: *244286 [lua] base_plugin.lua:20: rewrite(): executing plugin "statsd": rewrite
2017/12/11 16:35:02 [debug] 59#0: *244286 [lua] base_plugin.lua:24: access(): executing plugin "statsd": access
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [error] 59#0: *244286 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/events/lastEventTime HTTP/1.1", upstream: "http://11.211.103.77:9000/api/events/lastEventTime", host: "<REDACTED>"
2017/12/11 16:35:02 [debug] 59#0: *244292 [lua] base_plugin.lua:20: rewrite(): executing plugin "statsd": rewrite
2017/12/11 16:35:02 [debug] 59#0: *244292 [lua] base_plugin.lua:24: access(): executing plugin "statsd": access
2017/12/11 16:35:02 [debug] 59#0: *244292 [lua] base_plugin.lua:28: header_filter(): executing plugin "statsd": header_filter
2017/12/11 16:35:02 [debug] 59#0: *244292 [lua] base_plugin.lua:32: body_filter(): executing plugin "statsd": body_filter
2017/12/11 16:35:02 [debug] 59#0: *244292 [lua] base_plugin.lua:32: body_filter(): executing plugin "statsd": body_filter
2017/12/11 16:35:02 [debug] 59#0: *244292 [lua] base_plugin.lua:36: log(): executing plugin "statsd": log
2017/12/11 16:35:02 [debug] 59#0: *244294 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.count:1|c
2017/12/11 16:35:02 [debug] 59#0: *244294 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.latency:14|ms
2017/12/11 16:35:02 [debug] 59#0: *244294 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.size:239|ms
2017/12/11 16:35:02 [debug] 59#0: *244294 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.200:1|c
2017/12/11 16:35:02 [debug] 59#0: *244294 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.request.status.total:1|c
2017/12/11 16:35:02 [debug] 59#0: *244294 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.response.size:270|ms
2017/12/11 16:35:02 [debug] 59#0: *244294 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.upstream_latency:14|ms
2017/12/11 16:35:02 [debug] 59#0: *244294 [lua] statsd_logger.lua:67: send_statsd(): sending data to statsd server: kong.EventsDashboard.kong_latency:0|ms
2017/12/11 16:35:03 [debug] 59#0: *244286 [lua] base_plugin.lua:28: header_filter(): executing plugin "statsd": header_filter
protetore commented 6 years ago

These are the DNS queries:

[n02 ~]# dig figsworkbench-dashboard.marathon.l4lb.thisdcos.directory

; <<>> DiG 9.9.4-RedHat-9.9.4-38.el7_3.2 <<>> figsworkbench-dashboard.marathon.l4lb.thisdcos.directory
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 59556
;; flags: qr aa rd; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; WARNING: recursion requested but not available

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;figsworkbench-dashboard.marathon.l4lb.thisdcos.directory. IN A

;; ANSWER SECTION:
figsworkbench-dashboard.marathon.l4lb.thisdcos.directory. 5 IN A 11.211.103.77

;; Query time: 1 msec
;; SERVER: 198.51.100.1#53(198.51.100.1)
;; WHEN: Mon Dec 11 17:54:25 CET 2017
;; MSG SIZE  rcvd: 101

[n02 ~]# dig figsworkbench-dashboard.marathon.l4lb.thisdcos.directory SRV

; <<>> DiG 9.9.4-RedHat-9.9.4-38.el7_3.2 <<>> figsworkbench-dashboard.marathon.l4lb.thisdcos.directory SRV
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 23205
;; flags: qr aa rd; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1
;; WARNING: recursion requested but not available

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;figsworkbench-dashboard.marathon.l4lb.thisdcos.directory. IN SRV

;; AUTHORITY SECTION:
l4lb.thisdcos.directory. 1      IN      SOA     ns.l4lb.thisdcos.directory. support.mesosphere.com. 1513055745 5 5 5 1

;; Query time: 1 msec
;; SERVER: 198.51.100.1#53(198.51.100.1)
;; WHEN: Mon Dec 11 17:55:02 CET 2017
;; MSG SIZE  rcvd: 146

[dig figsworkbench-dashboard.marathon.l4lb.thisdcos.directory CNAME

; <<>> DiG 9.9.4-RedHat-9.9.4-38.el7_3.2 <<>> figsworkbench-dashboard.marathon.l4lb.thisdcos.directory CNAME
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 12171
;; flags: qr aa rd; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1
;; WARNING: recursion requested but not available

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;figsworkbench-dashboard.marathon.l4lb.thisdcos.directory. IN CNAME

;; AUTHORITY SECTION:
l4lb.thisdcos.directory. 1      IN      SOA     ns.l4lb.thisdcos.directory. support.mesosphere.com. 1513055745 5 5 5 1

;; Query time: 1 msec
;; SERVER: 198.51.100.1#53(198.51.100.1)
;; WHEN: Mon Dec 11 17:55:41 CET 2017
;; MSG SIZE  rcvd: 146
Tieske commented 6 years ago

these are fully qualified dig lookups. Please provide the shortname lookup, as mentioned here:

What do your dns records look like? Eg. what is the output of dig figsworkbench-dashboard SRV? (please also for A and CNAME)

Tieske commented 6 years ago

also the log shows 1 error (one timestamp, 2017/12/11 16:34:53 to 16:34:55) what happens if you keep it running longer, what is the interval between multiple occurences of the error.

protetore commented 6 years ago

these are fully qualified dig lookups. Please provide the shortname lookup, as mentioned here:

It's the same, but we have to use dig +search so it can use the search list in resolv.conf, otherwise dig won't find the address.

[n02 ~]# dig figsworkbench-dashboard +search

; <<>> DiG 9.9.4-RedHat-9.9.4-38.el7_3.2 <<>> figsworkbench-dashboard +search
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 62554
;; flags: qr aa rd; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; WARNING: recursion requested but not available

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;figsworkbench-dashboard.marathon.l4lb.thisdcos.directory. IN A

;; ANSWER SECTION:
figsworkbench-dashboard.marathon.l4lb.thisdcos.directory. 5 IN A 11.211.103.77

;; Query time: 1 msec
;; SERVER: 198.51.100.1#53(198.51.100.1)
;; WHEN: Mon Dec 11 18:50:19 CET 2017
;; MSG SIZE  rcvd: 101

[n02 ~]# dig figsworkbench-dashboard +search SRV

; <<>> DiG 9.9.4-RedHat-9.9.4-38.el7_3.2 <<>> figsworkbench-dashboard +search SRV
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 64068
;; flags: qr aa rd; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1
;; WARNING: recursion requested but not available

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;figsworkbench-dashboard.marathon.l4lb.thisdcos.directory. IN SRV

;; AUTHORITY SECTION:
l4lb.thisdcos.directory. 1      IN      SOA     ns.l4lb.thisdcos.directory. support.mesosphere.com. 1513060834 5 5 5 1

;; Query time: 1 msec
;; SERVER: 198.51.100.1#53(198.51.100.1)
;; WHEN: Mon Dec 11 18:53:27 CET 2017
;; MSG SIZE  rcvd: 146

[n02 ~]# dig figsworkbench-dashboard +search CNAME

; <<>> DiG 9.9.4-RedHat-9.9.4-38.el7_3.2 <<>> figsworkbench-dashboard +search CNAME
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 28557
;; flags: qr aa rd; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1
;; WARNING: recursion requested but not available

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;figsworkbench-dashboard.marathon.l4lb.thisdcos.directory. IN CNAME

;; AUTHORITY SECTION:
l4lb.thisdcos.directory. 1      IN      SOA     ns.l4lb.thisdcos.directory. support.mesosphere.com. 1513060866 5 5 5 1

;; Query time: 1 msec
;; SERVER: 198.51.100.1#53(198.51.100.1)
;; WHEN: Mon Dec 11 18:53:54 CET 2017
;; MSG SIZE  rcvd: 146

Without +search it's looking for an address that doesn't exist:

n02 ~]# dig figsworkbench-dashboard

; <<>> DiG 9.9.4-RedHat-9.9.4-38.el7_3.2 <<>> figsworkbench-dashboard
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 54860
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;figsworkbench-dashboard.       IN      A

;; AUTHORITY SECTION:
.                       6980    IN      SOA     a.root-servers.net. nstld.verisign-grs.com. 2017121100 1800 900 604800 86400

;; Query time: 4 msec
;; SERVER: 198.51.100.1#53(198.51.100.1)
;; WHEN: Mon Dec 11 18:55:25 CET 2017
;; MSG SIZE  rcvd: 127
Tieske commented 6 years ago

I think if you set the dns_stale_ttl=120, then that will resolve the error. You can also set the environment variable KONG_DNS_STALE_TTL=120

Can you give that a try?

grillorafael commented 6 years ago

Yep. I'll ping you here later on

grillorafael commented 6 years ago

Still see it happening but I don't see this say error anymore.

Kong instance just gets stuck and stop serving other requests. Looks like it is queuing in a way and if I access the upstream address directly everything works fine and fast.

The last error I saw was this:

2017/12/12 10:28:14 [error] 55#0: *7163 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=9674804&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=9674804&eventTypes=draft%2Cenhanced_stop_begin%2Cenhanced_stop_end%2Cport_enter%2Cport_exit%2Cbunkering%2Cpossible_bunkering%2Cdata_issues_bunkering%2Cno_position_message_start%2Cno_position_message_end%2Cproximity_end%2Cpossible_proximity_end%2Cside_by_side_end%2Cfacility_enter%2Cfacility_exit%2Cberth_enter%2Cberth_exit%2Cdestination%2Ceta&pageSize=1", host: "<redacted>"
2017/12/12 10:28:14 [error] 55#0: *7176 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?imos=9043720&page=0&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?imos=9043720&page=0&pageSize=100", host: "<redacted>"
2017/12/12 10:28:14 [error] 55#0: *7177 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=7382603&eventTypes=destination&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=7382603&eventTypes=destination&pageSize=1", host: "<redacted>"
2017/12/12 10:28:14 [error] 55#0: *7178 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/events?imos=7724045&eventTypes=eta&pageSize=1 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/events?imos=7724045&eventTypes=eta&pageSize=1", host: "<redacted>"
2017/12/12 10:28:14 [error] 55#0: *7179 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 10.250.3.2, server: kong, request: "GET /api/v1/client/state/expanded?imos=9768758&page=0&pageSize=100 HTTP/1.1", upstream: "http://11.211.103.77:9000/api/v1/client/state/expanded?imos=9768758&page=0&pageSize=100", host: "<redacted>"

EDIT: Those apis are very fast ones (under 1sec)

grillorafael commented 6 years ago

Usually when I restart Kong instance things go back to normal.

Tieske commented 6 years ago

k, so your problem is not DNS related. The stale_ttl setting is a workaround for your low request volume combined with a long-running request, which gets a timeout.

Though I'm puzzled now by what might cause this issue.

@hishamhm @p0pr0ck5 ideas?

grillorafael commented 6 years ago

Please let me know what else I can provide to deal with this. I'm delegating the blame to Kong because when I access the upstream directly I see no issues.

I'm using:

Docker image: kong:0.11.2 Command: export KONG_NGINX_DAEMON="off" && kong migrations up && kong prepare -p /usr/local/kong/ && /usr/local/openresty/nginx/sbin/nginx -c /usr/local/kong/nginx.conf -p /usr/local/kong/

image

p0pr0ck5 commented 6 years ago

At this point I would start trying to capture some network traffic during these timeout events to see what's going on, as well as examining the logs of the upstream servers during these periods.

grillorafael commented 6 years ago

The upstream servers are well and alive from the checks I've made. They have no error in their logs and while the request through Kong is stuck, I'm fully able to throw hundreds of requests directly to the upstream.

I'll try to get some of the network logs

grillorafael commented 6 years ago

I saw the issue happening again and nothing notable on kong logs, upstream logs or anything else.

I noticed that when it happens, just the service I'm trying to load hangs but other services are fine. Is there any concurrency config per service?

Tieske commented 6 years ago

just the service I'm trying to load hangs

What do you mean by this, what service are you talking about? is it a Kong node, a Kong worker process, your won backend services? please be more specific.

donalddewulf commented 6 years ago

@grillorafael Did you manage to resolve this issue? I'm seeing similar errors, might not be related, but I'm desperate at this point :)

grillorafael commented 6 years ago

Hey @donalddewulf I still have this issue. Didn't solve yet

@Tieske I have many APIs in Kong at the moment (~6) and when it hangs is just one of the apis. Usually when I restart Kong things go back to normal and while it hangs, I can access the api directly (not going through kong) without an issue.

Tieske commented 6 years ago

@grillorafael This really looks like the backend is not responding to Kong. The way the internals of nginx/openresty/kong work is that individual worker processes interleave work for multiple requests simultaneously (known as cooperative multithreading). If "hanging" would mean a blocked worker process, then it would fail to serve any request. Since in your case it is only a single API, it seems the requests hang waiting on socket communications (while the worker continues dealing with the other apis/requests). Which in turn leads us to believe that your backend is not behaving properly (or Kong for that matter).

So as @p0pr0ck5 mentioned before:

At this point I would start trying to capture some network traffic during these timeout events to see what's going on, as well as examining the logs of the upstream servers during these periods.

grillorafael commented 6 years ago

@Tieske I'll try to further investigate this here on my end. I'll reopen in case I get something.

grillorafael commented 6 years ago

Hi All,

I'll reopen the issue as I gathered more information.

We are now using Kong 0.13 and we see the issue happening once we make a deploy in our DCOS cluster (Version 1.10.0).

When a deploy happens, kong suddenly stops resolving DNS properly and we see the following errors:

2018/03/30 23:47:09 [error] 52#0: *1350788 [lua] balancer.lua:781: balancer_execute(): [dns] dns server error: 100 cache only lookup failed. Tried: (short)grapesworkbench-dashboard:(na) - cache-miss
grapesworkbench-dashboard.marathon.l4lb.thisdcos.directory:33 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard.l4lb.thisdcos.directory:33 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard.marathon.mesos:33 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard.cv.vpc:33 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard:33 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard.marathon.l4lb.thisdcos.directory:1 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard.l4lb.thisdcos.directory:1 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard.marathon.mesos:1 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard.cv.vpc:1 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard:1 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard.marathon.l4lb.thisdcos.directory:5 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard.l4lb.thisdcos.directory:5 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard.marathon.mesos:5 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard.cv.vpc:5 - cache only lookup failed/dns server error: 100 cache only lookup failed
grapesworkbench-dashboard:5 - cache only lookup failed/dns server error: 100 cache only lookup failed
grillorafael commented 6 years ago

We are using Posgres in RDS but Kong is connected to a pgbouncer and we also see the following error:

2018/03/30 19:25:27 [error] 56#0: *460700 [lua] cluster_events.lua:356: [cluster_events] poll() threw an error: /usr/local/share/lua/5.1/pgmoon/init.lua:233: attempt to index local 'sock' (a nil value), context: ngx.timer
2018/03/30 19:25:33 [error] 55#0: *460812 lua entry thread aborted: runtime error: /usr/local/share/lua/5.1/pgmoon/init.lua:233: attempt to index local 'sock' (a nil value)
stack traceback:
coroutine 0:
    /usr/local/share/lua/5.1/pgmoon/init.lua: in function 'keepalive'
    /usr/local/share/lua/5.1/kong/dao/db/postgres.lua:354: in function 'query'
    /usr/local/share/lua/5.1/kong/dao/db/postgres.lua:184: in function 'clear_expired_ttl'
    /usr/local/share/lua/5.1/kong/dao/db/postgres.lua:218: in function </usr/local/share/lua/5.1/kong/dao/db/postgres.lua:213>, context: ngx.timer
Tieske commented 6 years ago

regarding the DNS error, you're getting the "cache only lookup" error. This means that the initial connection failed (or returned are retry-able error), and Kong retries. During this retry, Kong has no sockets available and can only do dns resolution from cache. In this case the cache does not contain the name to be resolved. The error message contains the histroy of what was tried, <name>:<type>, where types are: 33 SRV, 1 A, 5 CNAME

This can happen in specific cases, long running requests (request takes longer than dns TTL, or a very short TTL as laternative). Or with very low request volume (DNS is only resolved upon a request)

What is the TTL for your dns records?

grillorafael commented 6 years ago

Those records are being resolved by Spartan and the TTL for them is 5 seconds from what I saw here