Kong: Kong routes traffic to deleted targets

[zeeshen]

Summary

Kong routes traffic to deleted targets.

Steps To Reproduce

1. Start 2 upstream servers, let's say server1 listening on localhost:8881, server2 listening on localhost:8882.
   Server code:

package main

import (
    "fmt"
    "flag"
    "net/http"
)

var (
    port int
    name string
)

func main() {
    flag.IntVar(&port, "port", 8080, "http server port")
    flag.StringVar(&name, "name", "me", "http server name")
    flag.Parse()

    http.HandleFunc("/about", func (w http.ResponseWriter, r *http.Request) {
        fmt.Fprintf(w, "this is %s, listening on port %d", name, port)
    })

    http.ListenAndServe(fmt.Sprintf(":%d", port), nil)
}

1. Add a route and related resources. Add server1 as the upstream's target.

curl -i -X POST \
  --url http://localhost:8001/upstreams/ \
  --data 'name=myupstream'

curl -s -X POST --url http://localhost:8001/upstreams/myupstream/targets --data 'target=127.0.0.1:8881'

curl -i -X POST \
  --url http://localhost:8001/services/ \
  --data 'name=example-service' \
  --data 'url=http://myupstream'

curl -i -X POST \
  --url http://localhost:8001/services/example-service/routes \
  --data 'hosts[]=routea.com' \
  --data 'name=routea'

1. Delete a target 127.0.0.1:8881, add a target 127.0.0.1:8882

 curl -i -X DELETE --url http://localhost:8001/upstreams/myupstream/targets/127.0.0.1:8881 && curl -i -X POST --url http://localhost:8001/upstreams/myupstream/targets --data 'target=127.0.0.1:8882'

1. Send some requests to Kong and check response, you'll find that Kong's still routing (some) requests to the deleted target server1(listening on 8881). But via admin api, you can find just only one target of this upstream and it's server2(127.0.0.1:8882).

curl localhost:8000/about -H "Host: routea.com" -H "Kong-Debug: true" -i
HTTP/1.1 200 OK
Content-Type: text/plain; charset=utf-8
Content-Length: 36
Connection: keep-alive
Kong-Route-Id: 26c1a714-06c1-440d-a426-31c7566a4a92
Kong-Route-Name: routea
Kong-Service-Id: 781a15b0-eb78-47f5-bcd3-5ad387bf8a1a
Kong-Service-Name: example-service
Date: Mon, 29 Jul 2019 10:45:06 GMT
X-Kong-Upstream-Latency: 1
X-Kong-Proxy-Latency: 0
Via: kong/1.2.1

this is zero, listening on port 8881

Additional Details & Logs

• Kong version: 1.2.1
• Kong error logs:
  2019/07/29 18:38:00 [warn] 65268#0: *18847 [lua] ring.lua:238: redistributeIndices(): [ringbalancer 1] redistributed indices, size=10000, dropped=10000, assigned=0, left unassigned=10000, client: 127.0.0.1, server: kong_admin, request: "DELETE /upstreams/myupstream/targets/127.0.0.1:8881 HTTP/1.1", host: "localhost:8001" 2019/07/29 18:38:00 [notice] 65268#0: *18847 [lua] targets.lua:64: clean_history(): [Target DAO] Starting cleanup of target table for upstream 54f2a833-42c9-48a3-929a-6ee5bf46231e, client: 127.0.0.1, server: kong_admin, request: "DELETE /upstreams/myupstream/targets/127.0.0.1:8881 HTTP/1.1", host: "localhost:8001" 2019/07/29 18:38:00 [info] 65268#0: *18847 [lua] targets.lua:77: clean_history(): [Target DAO] Finished cleanup of target table for upstream 54f2a833-42c9-48a3-929a-6ee5bf46231e removed 2 target entries, client: 127.0.0.1, server: kong_admin, request: "DELETE /upstreams/myupstream/targets/127.0.0.1:8881 HTTP/1.1", host: "localhost:8001" 2019/07/29 18:38:00 [info] 65268#0: *18847 kevent() reported that client 127.0.0.1 closed keepalive connection 2019/07/29 18:38:00 [info] 65268#0: *18850 kevent() reported that client 127.0.0.1 closed keepalive connection 2019/07/29 18:38:01 [error] 65269#0: *18855 [lua] balancer.lua:267: [healthchecks] failed setting peer status: no peer found by name '127.0.0.1' and address 127.0.0.1:8882, context: ngx.timer 2019/07/29 18:38:01 [error] 65275#0: *18858 [lua] balancer.lua:267: [healthchecks] failed setting peer status: no peer found by name '127.0.0.1' and address 127.0.0.1:8882, context: ngx.timer 2019/07/29 18:38:01 [error] 65270#0: *18873 [lua] balancer.lua:267: [healthchecks] failed setting peer status: no peer found by name '127.0.0.1' and address 127.0.0.1:8882, context: ngx.timer 2019/07/29 18:38:01 [error] 65274#0: *18860 [lua] balancer.lua:267: [healthchecks] failed setting peer status: no peer found by name '127.0.0.1' and address 127.0.0.1:8882, context: ngx.timer 2019/07/29 18:38:01 [error] 65272#0: *18859 [lua] balancer.lua:267: [healthchecks] failed setting peer status: no peer found by name '127.0.0.1' and address 127.0.0.1:8882, context: ngx.timer 2019/07/29 18:38:01 [error] 65271#0: *18861 [lua] balancer.lua:267: [healthchecks] failed setting peer status: no peer found by name '127.0.0.1' and address 127.0.0.1:8882, context: ngx.timer 2019/07/29 18:38:01 [error] 65273#0: *18862 [lua] balancer.lua:267: [healthchecks] failed setting peer status: no peer found by name '127.0.0.1' and address 127.0.0.1:8882, context: ngx.timer
• Kong configuration: default config
• Operating system: linux/osx

[zeeshen]

Looked into debug log and found that only one worker rebuilt the ring balancer after step2(Delete a target 127.0.0.1:8881, add a target 127.0.0.1:8882). Other workers just fetched targets for upstream but didn't rebuild the ring balancer.

Debug error:

cat logs/error.log | grep -E "fetching targets for upstream|removeHost|new address for host|Starting cleanup of target"
2019/07/29 20:46:34 [debug] 83340#0: *2711 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:34 [debug] 83340#0: *2711 [lua] base.lua:905: removeHost(): [ringbalancer 2] removing host 127.0.0.1:8881
2019/07/29 20:46:34 [notice] 83340#0: *2711 [lua] targets.lua:64: clean_history(): [Target DAO] Starting cleanup of target table for upstream 4af970ea-ab3f-4f91-b089-a324389c0447, client: 127.0.0.1, server: kong_admin, request: "DELETE /upstreams/myupstream/targets/127.0.0.1:8881 HTTP/1.1", host: "localhost:8001"
2019/07/29 20:46:34 [debug] 83340#0: *2711 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:34 [debug] 83340#0: *2711 [lua] base.lua:304: newAddress(): [ringbalancer 3] new address for host '127.0.0.1' created: 127.0.0.1:8881 (weight 100)
2019/07/29 20:46:34 [debug] 83340#0: *2711 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:34 [debug] 83340#0: *2714 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:34 [debug] 83340#0: *2714 [lua] base.lua:304: newAddress(): [ringbalancer 4] new address for host '127.0.0.1' created: 127.0.0.1:8882 (weight 100)
2019/07/29 20:46:35 [debug] 83342#0: *2731 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83342#0: *2731 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83342#0: *2731 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83342#0: *2731 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83348#0: *2738 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83348#0: *2738 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83348#0: *2738 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83344#0: *2739 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83346#0: *2735 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83346#0: *2735 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83346#0: *2735 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83344#0: *2739 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83344#0: *2739 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83347#0: *2745 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83347#0: *2745 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83347#0: *2745 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83347#0: *2745 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83343#0: *2746 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83343#0: *2746 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83343#0: *2746 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83343#0: *2746 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83341#0: *2742 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83341#0: *2742 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447
2019/07/29 20:46:35 [debug] 83341#0: *2742 [lua] balancer.lua:123: fetching targets for upstream: 4af970ea-ab3f-4f91-b089-a324389c0447

[locao]

@zeeshen we were not able to reproduce the issue. Could you test with version 1.3.0rc1 to check if the problem persists, please?

[guanlan]

@zeeshen Can you update the 1.3.0 and give it a try?

[zeeshen]

We tried the 1.3.0 version and this bug still exists.

In step 2: we use an && to ensure the 2nd request is sent immediately after the 1st request.
In step 3: tools like wrk may be helpful as not all the workers' routing are incorrect.

Some logs, hope it can help:

debug log during the target modifications requests:

2019/09/04 11:36:04 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:acce9355-d3fb-4375-af9c-705ef4260265::::
2019/09/04 11:36:04 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd956d43c88
2019/09/04 11:36:04 [debug] 20550#0: *267633158 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:04 [debug] 20550#0: *267633158 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=remove, pid=20551, data=table: 0x7fd956d44520
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target '127.0.0.1 (127.0.0.1:8881' removed
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target '127.0.0.1 (127.0.0.1:8881' removed
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:acce9355-d3fb-4375-af9c-705ef4260265::::
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd956afb6b0
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=clear, pid=20551, data=table: 0x7fd956affe70
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=healthy, pid=20551, data=table: 0x7fd956b001b8
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8881)'
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8881)' from 'false' to 'true'
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8881)'
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8881)' from 'false' to 'true'
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:30816424-4200-42ef-8123-26e1225730ce::::
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd956b00f20
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=clear, pid=20551, data=table: 0x7fd9569b9a18
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:98e362b2-3b0b-4fe3-87c1-e77b6611849a::::
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd9569b9f18
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=healthy, pid=20551, data=table: 0x7fd955b1d5c0
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8882)'
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8882)' from 'false' to 'true'
2019/09/04 11:36:05 [error] 20550#0: *267633158 [lua] balancer.lua:283: [healthchecks] failed setting peer status: no peer found by name '127.0.0.1' and address 127.0.0.1:8882, context: ngx.timer
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8882)'
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8882)' from 'false' to 'true'
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20550#0: *267633158 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:acce9355-d3fb-4375-af9c-705ef4260265::::
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd956a1fe28
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=remove, pid=20551, data=table: 0x7fd95875ba90
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target '127.0.0.1 (127.0.0.1:8881' removed
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target '127.0.0.1 (127.0.0.1:8881' removed
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:acce9355-d3fb-4375-af9c-705ef4260265::::
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd9585753c0
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=clear, pid=20551, data=table: 0x7fd9585fe2c8
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=healthy, pid=20551, data=table: 0x7fd95874d4d8
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8881)'
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8881)' from 'false' to 'true'
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8881)'
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8881)' from 'false' to 'true'
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:30816424-4200-42ef-8123-26e1225730ce::::
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd9586d7d68
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=clear, pid=20551, data=table: 0x7fd95864d5f8
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:98e362b2-3b0b-4fe3-87c1-e77b6611849a::::
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd9588e6580
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=healthy, pid=20551, data=table: 0x7fd9588675f8
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8882)'
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8882)' from 'false' to 'true'
2019/09/04 11:36:05 [error] 20549#0: *267633175 [lua] balancer.lua:283: [healthchecks] failed setting peer status: no peer found by name '127.0.0.1' and address 127.0.0.1:8882, context: ngx.timer
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8882)'
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8882)' from 'false' to 'true'
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20549#0: *267633175 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:acce9355-d3fb-4375-af9c-705ef4260265::::
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd9563d9d70
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=remove, pid=20551, data=table: 0x7fd9599ede88
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target '127.0.0.1 (127.0.0.1:8881' removed
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target '127.0.0.1 (127.0.0.1:8881' removed
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:acce9355-d3fb-4375-af9c-705ef4260265::::
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd9599ee430
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=clear, pid=20551, data=table: 0x7fd95830f198
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=healthy, pid=20551, data=table: 0x7fd95830f4e0
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8881)'
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8881)' from 'false' to 'true'
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8881)'
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8881)' from 'false' to 'true'
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:30816424-4200-42ef-8123-26e1225730ce::::
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd9580fd930
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=clear, pid=20551, data=table: 0x7fd9563b4c38
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: local cache cleared
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=targets:98e362b2-3b0b-4fe3-87c1-e77b6611849a::::
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=balancer, event=targets, pid=20551, data=table: 0x7fd9563b5230
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] cache.lua:289: invalidate_local(): [DB cache] invalidating (local): 'balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5'
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] balancer.lua:123: fetching targets for upstream: c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20551, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=lua-resty-healthcheck [myupstream], event=healthy, pid=20551, data=table: 0x7fd95838a3f8
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8882)'
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8882)' from 'false' to 'true'
2019/09/04 11:36:05 [error] 20552#0: *267633190 [lua] balancer.lua:283: [healthchecks] failed setting peer status: no peer found by name '127.0.0.1' and address 127.0.0.1:8882, context: ngx.timer
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target added '127.0.0.1(127.0.0.1:8882)'
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] healthcheck.lua:1014: log(): [healthcheck] (myupstream) event: target status '127.0.0.1(127.0.0.1:8882)' from 'false' to 'true'
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20552#0: *267633190 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20550, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:05 [debug] 20551#0: *267633196 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20550#0: *267633225 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20550#0: *267633225 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20550#0: *267633225 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20550#0: *267633225 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20549, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20550#0: *267633225 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20550#0: *267633225 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20550#0: *267633225 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20550#0: *267633225 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20549#0: *267633241 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20549#0: *267633241 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20549#0: *267633241 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:06 [debug] 20549#0: *267633241 [lua] events.lua:211: do_event_json(): worker-events: handling event; source=mlcache, event=mlcache:invalidations:kong_db_cache, pid=20552, data=balancer:targets:c18a474c-4f9a-4bcd-8ec5-fda6eda3a6d5
2019/09/04 11:36:54 [debug] 20552#0: *267645311 [lua] cluster_events.lua:224: [cluster_events] polling events from: 1567596834.102 to: 1567597014.118

access log 2 mins+ after the target modifications requests: requests handled by the worker#20551 were routed to the correct target 127.0.0.1:8882, others were not

{"time": "04/Sep/2019:11:38:01 +0000","_timestamp": "1567597081.506","client_ip": "-","upstream_addr": "127.0.0.1:8882, 127.0.0.1:8882, 127.0.0.1:8882, 127.0.0.1:8882, 127.0.0.1:8882, 127.0.0.1:8882","host": "routea.com","req": "GET / HTTP/1.1","req_traceid": "-","resp_code": "502","resp_body_bytes": "69","referrer": "-","user_agent": "-","req_time": "0.000","upstream_time": "0.000, 0.000, 0.000, 0.000, 0.000, 0.000","upstream_conn_time": "-, -, -, -, -, -","upstream_time_header": "0","kong_time": "0","upstream_login": "-","upstream_traceid": "-","remote_user": "-","pid": "20551"}
...
{"time": "04/Sep/2019:11:38:01 +0000","_timestamp": "1567597081.645","client_ip": "-","upstream_addr": "127.0.0.1:8881, 127.0.0.1:8881, 127.0.0.1:8881, 127.0.0.1:8881, 127.0.0.1:8881, 127.0.0.1:8881","host": "routea.com","req": "GET / HTTP/1.1","req_traceid": "-","resp_code": "502","resp_body_bytes": "69","referrer": "-","user_agent": "-","req_time": "0.000","upstream_time": "0.000, 0.000, 0.000, 0.000, 0.000, 0.000","upstream_conn_time": "-, -, -, -, -, -","upstream_time_header": "0","kong_time": "0","upstream_login": "-","upstream_traceid": "-","remote_user": "-","pid": "20552"}

{"time": "04/Sep/2019:11:58:47 +0000","_timestamp": "1567598327.238","client_ip": "-","upstream_addr": "127.0.0.1:8881, 127.0.0.1:8881, 127.0.0.1:8881, 127.0.0.1:8881, 127.0.0.1:8881, 127.0.0.1:8881","host": "routea.com","req": "GET / HTTP/1.1","req_traceid": "-","resp_code": "502","resp_body_bytes": "69","referrer": "-","user_agent": "-","req_time": "0.000","upstream_time": "0.000, 0.000, 0.000, 0.000, 0.000, 0.000","upstream_conn_time": "-, -, -, -, -, -","upstream_time_header": "0","kong_time": "0","upstream_login": "-","upstream_traceid": "-","remote_user": "-","pid": "20549"}
{"time": "04/Sep/2019:11:58:47 +0000","_timestamp": "1567598327.240","client_ip": "-","upstream_addr": "127.0.0.1:8882, 127.0.0.1:8882, 127.0.0.1:8882, 127.0.0.1:8882, 127.0.0.1:8882, 127.0.0.1:8882","host": "routea.com","req": "GET / HTTP/1.1","req_traceid": "-","resp_code": "502","resp_body_bytes": "69","referrer": "-","user_agent": "-","req_time": "0.000","upstream_time": "0.000, 0.000, 0.000, 0.000, 0.000, 0.000","upstream_conn_time": "-, -, -, -, -, -","upstream_time_header": "0","kong_time": "0","upstream_login": "-","upstream_traceid": "-","remote_user": "-","pid": "20551"}

[zeeshen]

hey guys, I added some log code(based on 1.3.0) and may find the cause.
full diff
full log

--- a/kong/runloop/balancer.lua
+++ b/kong/runloop/balancer.lua
@@ -458,6 +460,11 @@ local function check_target_history(upstream, balancer)
     (old_history[old_size] or EMPTY_T).order ==
     (new_history[new_size] or EMPTY_T).order then
     -- No history update is necessary in the balancer object.
+    local o = old_history[old_size] or EMPTY_T
+    local n = new_history[new_size] or EMPTY_T
+    log(DEBUG, "mark-l464: check target no change, old: order " , o.order , ", target "
+      , o.target , ", weight " , o.weight
+      , ", new: order " , n.order , ", target " , n.target , ", weight " , n.weight)
     return true
   end

2019/09/05 08:12:47 [debug] 25393#0: *354 [lua] targets.lua:207: select_by_upstream_raw(): mark-l207: select_by_upstream_raw targets: 127.0.0.1:8882(order: nil)
2019/09/05 08:12:47 [debug] 25393#0: *354 [lua] balancer.lua:465: check_target_history(): mark-l464: check target no change, old: order nil, target nil, weight 100, new: order nil, target 127.0.0.1:8882, weight 100

From the log, we can see all the target.orders in balancer.lua are nil as the order field is unset in select_by_upstream_raw. So during rapid target changes, the rebuild process will be skipped if the targets length is unchanged.

This bug may be introduced by this commit. This commit removed the call of add_order in select_by_upstream_raw.