search

Kong / kong

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

Kong and Cassandra, observed behaviors/paging issues #4769

Closed jeremyjpj0916 closed 4 years ago

jeremyjpj0916 commented 5 years ago

Summary

Continuation cleaned up of https://github.com/Kong/kong/issues/4194 , it was getting way too long and had old discussions on older Kong version vs modern issues trying to triage.

With keepalive problem we had had pretty much figured out now(https://github.com/Kong/openresty-patches/pull/40), this is the only hurdle we see left with running Kong, so lets crack the last mystery so I can crown this Gorilla 🐒.

Summary of issues seen:

  1. Once route/service/plugins maps get big enough(couple thousand records each), the paging through C* can produce NPEs(https://github.com/Kong/kong/issues/4194#issuecomment-497572751). Seemingly occurs when Kong pages across multiple Cassandra nodes in the cluster for us.

Oddly something that seems to fix it is to sticky persist to a C* node during the rebuild. I accomplished this by modifying the concurrency.lua file as described here: https://github.com/Kong/kong/issues/4194#issuecomment-498001854

This is a bandaid approach though and I don't wanna run this if I can avoid it, its right and proper for Kong to be able to jump around when doing all this paging querying and jumping node to node should not be problem.

I think we can agree C* throwing a NPE is worthy of a JIRA task to them, I have an ASF Slack convo I had with some of them: https://the-asf.slack.com/archives/CJZLTM05A/p1559321422028200 And bits of the convo I pulled and posted here too: https://github.com/Kong/kong/issues/4194#issuecomment-497858824

I will try to raise that, but I don't know if I can give a good repro for them so they might be flying blind. But also per discussion could be a Kong DAO or Driver issue as well to nail down.

  1. Even with the above in place, there are portions I can't do sticky persist logic in design, think like the admin API specifically. So I observe when standing up service + route + plugins on rout, then tearing down route(which also deletes the plugins automagically). Then the call to delete the service will fail as described here: https://github.com/Kong/kong/issues/4194#issuecomment-498002915 https://github.com/Kong/kong/issues/4194#issuecomment-498117978 https://github.com/Kong/kong/issues/4194#issuecomment-498533977

Seems like specifically the cascading hot path on the service delete when its trying page_for_service(which does not seem to get invoked often in the path if I wait a second to delete the service after deleting a given route).

Diving deeper down the rabbit hole at this stage I have taken @thibaultcha shout on where in the C* driver I can log the queries a bit and given this snippit a go in the init.lua:

function _Host:execute(query, args, options)
  local opts = get_opts(options)
  local request = opts.prepared and
    -- query is the prepared query id
    requests.execute_prepared.new(query, args, opts)
    or
    requests.query.new(query, args, opts)

  if opts.prepared then
      ngx.log(ngx.ERR, "Execute_prepared called: " .. (query or "nil") .. " Args Table: " .. (table.tostring(args) or "nil") .. " Options Table: " .. (table.tostring(options) or "nil"))
  else
      ngx.log(ngx.ERR, "Regular Query called: " .. (query or "nil") .. " Args Table: " .. (table.tostring(args) or "nil") .. " Options Table: " .. (table.tostring(options) or "nil"))
  end

  return self:send(request)
end

Further details to be provided in comments after this initial post.

Steps To Reproduce

  1. I have no simple way to reproduce this. My advice to do so would be stand up a 6 node C cluster on RHEL VMs any C 3.x should do, 2 DC 3 C nodes per DC. Replicate data across all C nodes. Run Kong in the 2 DCs with a LOCAL_QUORUM approach to them running with the RequestDCAwareRoundRobin setting as well.

  2. Make thousands, say 3k of each to be safe of service+route+plugins on route combos.

  3. Write a script to add and remove a service+route+plugins combo value over and over again. Feel free to sleep a tad in between the loop if you don't want to chaos it too hard :) .

Additional Details & Logs

jeremyjpj0916 commented 5 years ago

First thing I thought to bring up, seems Kong on startup will grab by 1000 at a time on init, seems subsequent paging calls during regular runtime against admin api at the db level end up going by 100 sizes even if the original query was at size request of 1k? Is this desired behavior? See here:

2019/07/03 04:36:00 [error] 41#0: *15981 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {page_size=1000,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?size=1000 HTTP/1.1", host: "kong:8001"

2019/07/03 04:36:00 [error] 36#0: *15985 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="R[Oɤ�@ⳍ慼PĒ������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEFJbT8mk7kDys42WRTxQxJLwf%2F%2F8F%2FB%2F%2F%2FwX HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:00 [error] 36#0: *15995 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state='Z��}�Mڔ4䁳�"���������',page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEFqX0hd9tU3alDTkgbOOIpbwf%2F%2F7s%2FB%2F%2F%2Fuz HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:00 [error] 40#0: *15996 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="b��=vBm���W�z~���O���O",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEGIRtIk9dkJtlvzmV6x6fhDwf%2F%2F7T%2FB%2F%2F%2FtP HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:00 [error] 40#0: *15997 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="k)�5�D�����*�����������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEGsptBc13US6psztmyrthMrwf%2F%2F66%2FB%2F%2F%2Frr HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:00 [error] 40#0: *15998 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="s��6�J\�'ȾA��q��������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEHObpzaLEUpciSfIvkHZ5XHwf%2F%2F6h%2FB%2F%2F%2FqH HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:00 [error] 39#0: *15999 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="{���1tC��}�h� t  ���#���#",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEHu0ocwxdEOrqn3vaJ0gdAnwf%2F%2F6I%2FB%2F%2F%2Foj HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 36#0: *16003 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="���K��J��~o�PȬK��������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEISwkkuOuUrsj35vt1DIrEvwf%2F%2F5v%2FB%2F%2F%2Fm%2F HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 40#0: *16004 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="�/�M{�����j����[���[",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEIwvzrKc1U17rhWsiqyAaqfwf%2F%2F5W%2FB%2F%2F%2Flb HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 41#0: *16005 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="��3O!$C~�����˫Z��������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEJOlM08hJEN%2BuaKE0tfLq1rwf%2F%2F49%2FB%2F%2F%2Fj3 HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 40#0: *16012 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="�.Ȱ+�M   ��!����������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEJwuyLArkk0JrwQZ3wEhxM%2Fwf%2F%2F4k%2FB%2F%2F%2FiT HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 39#0: *16016 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="�:�=�9C6��gQ��g����/���/",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEKQ68z2TOUM2hdxnUfuVZ4%2Fwf%2F%2F4L%2FB%2F%2F%2Fgv HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 41#0: *16017 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="�G֜�Cp�`�ӳ[�4��������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEKxH1pwd%2FUNwjmCG07NbpDTwf%2F%2F3y%2FB%2F%2F%2FfL HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 36#0: *16021 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="�Y�uIN��>�9�e�����g���g",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAELRZ13VJAE6AuD6DOfFl76Dwf%2F%2F3Z%2FB%2F%2F%2Fdn HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 38#0: *16022 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="��h�ެL1�$~r_D������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAELyOaKLerEwxuSR%2BBnJfRAHwf%2F%2F3A%2FB%2F%2F%2FcD HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 36#0: *16023 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="ŕ31$�G���x�~̛���������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEMWVMzEknUeHpvd4137Mm7nwf%2F%2F2n%2FB%2F%2F%2Faf HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 36#0: *16024 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="�V�U�tI��d�H/��C���;���;",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEMxWkVW9dEm1g2SHSC%2FkgUPwf%2F%2F2O%2FB%2F%2F%2FY7 HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 39#0: *16028 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="�g����K!��   �b����������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAENRnke3Y%2FkshpuQJELBi7%2Fnwf%2F%2F11%2FB%2F%2F%2FXX HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 38#0: *16029 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="��^�)D���)������s���s",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEN4L4l7tKUSTltgIKf2JsBDwf%2F%2F1c%2FB%2F%2F%2FVz HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 38#0: *16030 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="��T��G��B2\����������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEOauVBymiUemt0IyXLmZyMbwf%2F%2F1D%2FB%2F%2F%2FUP HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 36#0: *16034 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="ﾋ�3�FÅ^�pU����������",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEO%2B%2Bi%2FAz%2BUbDhV67cBVVuZXwf%2F%2F0q%2FB%2F%2F%2FSr HTTP/1.1", host: "kong:8001"
2019/07/03 04:36:01 [error] 38#0: *16038 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services'
       Args Table: nil Options Table: {paging_state="�L��J�\
n�z����G���G",page_size=100,consistency=6,serial_consistency=8}, client: 10.131.42.1, server: kong_admin, request: "GET /services?offset=ABIAEPkETBPi1EobrlwNEG6gernwf%2F%2F0R%2FB%2F%2F%2FRH HTTP/1.1", host: "kong:8001"

My guess was this is due to here? https://github.com/Kong/kong/blob/0f2d77b678624b0383c0c80c01319cdee5b65cdb/kong/db/iteration.lua#L18

Also other places we can see 100: https://github.com/Kong/kong/blob/bc48efeabc5d7460271d09d20e8e95b1b2e97a04/kong/cluster_events/strategies/cassandra.lua#L29

https://github.com/Kong/kong/blob/152d88ced902722cdde895971ee887683357392b/kong/db/dao/init.lua#L511

https://github.com/Kong/kong/blob/152d88ced902722cdde895971ee887683357392b/kong/db/dao/init.lua#L783

https://github.com/Kong/kong/blob/152d88ced902722cdde895971ee887683357392b/kong/db/dao/init.lua#L826

https://github.com/Kong/kong/blob/bc48efeabc5d7460271d09d20e8e95b1b2e97a04/kong/cluster_events.lua#L22

Saw this one too but not sure what the 100 arg does here(page size default?): https://github.com/Kong/kong/blob/c17449f4cc931dd8aa4d37b978d0392982f4acc0/kong/db/strategies/cassandra/connector.lua#L145

Maybe the original size=1000 after the first paging call does not get a continuation and is lost subsequent paging so it goes back to defaulting to 100?

Probably would be a good perf fix to have the 1000 as opposed to 100 per the original size request(and default to 1000 regardless unless someone wants smaller).

Will continue my digging of the queries that occur under the NPE circumstances in my next post.

jeremyjpj0916 commented 5 years ago

Well it was not as insightful to me personally as I had hoped, this is what I see up until the deletion of the service resource(which had no plugins or anything associated to it) was deleted during the cascade service paging delete call path:


2019/07/03 06:02:57 [error] 41#0: *25681 [lua] init.lua:551: execute(): Regular Query called: SELECT * FROM system_schema.columns
--
  | WHERE keyspace_name = 'kong_dev'
  | AND table_name = 'oauth2_authorization_codes'
  | AND column_name = 'partition' Args Table: nil Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/66ca97a3-fafc-498d-8f0d-b83cbc064a30 HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:57 [error] 37#0: *25693 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="9�\|[,�D��� �d>����/",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:58 [error] 41#0: *25695 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {paging_state="��'T�H&�y���������/���/",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:58 [error] 41#0: *25681 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, created_at, service_id, credential_id, code, authenticated_userid, scope FROM oauth2_authorization_codes WHERE service_id = ?
  | Args Table: {{__cql_type=12,val="66ca97a3-fafc-498d-8f0d-b83cbc064a30"}} Options Table: {paging_state="��'T�H&�y���������/���/",page_size=1000,consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/66ca97a3-fafc-498d-8f0d-b83cbc064a30 HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:58 [error] 40#0: *25684 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="� Ml�Eޘ��y�����G",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:58 [error] 38#0: *25690 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="� Ml�Eޘ��y�����G",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:58 [error] 41#0: *25696 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="9�\|[,�D��� �d>����/",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:58 [error] 41#0: *25681 [lua] init.lua:1520: delete(): Error call info, Method: page_for_service Primary Key: {id="66ca97a3-fafc-498d-8f0d-b83cbc064a30"} Size: nil Offset: nil, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/66ca97a3-fafc-498d-8f0d-b83cbc064a30 HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:58 [error] 41#0: *25681 [kong] init.lua:98 could not gather associated entities for delete cascade: [cassandra] could not execute page query: [Server error] java.lang.NullPointerException, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/66ca97a3-fafc-498d-8f0d-b83cbc064a30 HTTP/1.1", host: "localhost:8001"

I found a block of DELETE query calls too from where my chaos script was running prior to the page_for_service delete cascade occurred/caused the npe error. Will refer to this as the happy path view of what the delete all look like as it deletes the route, plugins tied to route, and then eventually the service resource too:

2019/07/03 06:02:44 [error] 37#0: *24656 [lua] init.lua:551: execute(): Regular Query called:       DELETE FROM plugins WHERE id = ?
--
  | Args Table: {{__cql_type=12,val="eae1bc7b-8a50-4e5e-ba7d-1f302734d27a"}} Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /routes/0ed37e41-1e31-4fe1-aa0a-9ab17e080009 HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 37#0: *24656 [lua] init.lua:551: execute(): Regular Query called: SELECT * FROM system_schema.columns
  | WHERE keyspace_name = 'kong_dev'
  | AND table_name = 'routes'
  | AND column_name = 'partition' Args Table: nil Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /routes/0ed37e41-1e31-4fe1-aa0a-9ab17e080009 HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 37#0: *24656 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes' AND id = ?
  | Args Table: {{__cql_type=12,val="0ed37e41-1e31-4fe1-aa0a-9ab17e080009"}} Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /routes/0ed37e41-1e31-4fe1-aa0a-9ab17e080009 HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 37#0: *24656 [lua] init.lua:551: execute(): Regular Query called:         DELETE FROM routes WHERE partition = 'routes' AND id = ?
  | Args Table: {{__cql_type=12,val="0ed37e41-1e31-4fe1-aa0a-9ab17e080009"}} Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /routes/0ed37e41-1e31-4fe1-aa0a-9ab17e080009 HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 38#0: *25245 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 38#0: *25246 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 37#0: *25248 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 37#0: *25249 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *25251 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *25252 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services' AND id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 37#0: *25248 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {paging_state="Ono�D�i�J��������",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *25251 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {paging_state="Ono�D�i�J��������",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins WHERE service_id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {page_size=1000,consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, created_at, service_id, credential_id, code, authenticated_userid, scope FROM oauth2_authorization_codes WHERE service_id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {page_size=1000,consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 37#0: *25248 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {paging_state="��'T�H&�y���������/���/",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 38#0: *25246 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="Ϣ����L���\|d��=N���",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *25252 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="Ϣ����L���\|d��=N���",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 37#0: *25249 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="Ϣ����L���\|d��=N���",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, created_at, service_id, credential_id, token_type, expires_in, access_token, refresh_token, authenticated_userid, scope FROM oauth2_tokens WHERE service_id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {page_size=1000,consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 38#0: *25245 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {paging_state="Ono�D�i�J��������",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *25251 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {paging_state="��'T�H&�y���������/���/",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, created_at, service_id, credential_id, code, authenticated_userid, scope FROM oauth2_authorization_codes WHERE service_id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {page_size=1000,consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 37#0: *25248 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {paging_state="���%w�@W�ktK��r����G���G",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, created_at, service_id, credential_id, token_type, expires_in, access_token, refresh_token, authenticated_userid, scope FROM oauth2_tokens WHERE service_id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {page_size=1000,consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 38#0: *25246 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="9�\|[,�D��� �d>����/",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *25251 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {paging_state="���%w�@W�ktK��r����G���G",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called: SELECT * FROM system_schema.columns
  | WHERE keyspace_name = 'kong_dev'
  | AND table_name = 'routes'
  | AND column_name = 'partition' Args Table: nil Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 38#0: *25245 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {paging_state="��'T�H&�y���������/���/",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 37#0: *25249 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="9�\|[,�D��� �d>����/",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *25252 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="9�\|[,�D��� �d>����/",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes' AND service_id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 38#0: *25246 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="� Ml�Eޘ��y�����G",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called: SELECT * FROM system_schema.columns
  | WHERE keyspace_name = 'kong_dev'
  | AND table_name = 'plugins'
  | AND column_name = 'partition' Args Table: nil Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins WHERE service_id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {page_size=100,consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called: SELECT * FROM system_schema.columns
  | WHERE keyspace_name = 'kong_dev'
  | AND table_name = 'oauth2_authorization_codes'
  | AND column_name = 'partition' Args Table: nil Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, created_at, service_id, credential_id, code, authenticated_userid, scope FROM oauth2_authorization_codes WHERE service_id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {page_size=100,consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called: SELECT * FROM system_schema.columns
  | WHERE keyspace_name = 'kong_dev'
  | AND table_name = 'oauth2_tokens'
  | AND column_name = 'partition' Args Table: nil Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, created_at, service_id, credential_id, token_type, expires_in, access_token, refresh_token, authenticated_userid, scope FROM oauth2_tokens WHERE service_id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {page_size=100,consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 38#0: *25245 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, protocols, methods, hosts, paths, https_redirect_status_code, regex_priority, strip_path, preserve_host, snis, sources, destinations, tags, service_id FROM routes WHERE partition = 'routes'
  | Args Table: nil Options Table: {paging_state="���%w�@W�ktK��r����G���G",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 37#0: *25249 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="� Ml�Eޘ��y�����G",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *25252 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags FROM plugins
  | Args Table: nil Options Table: {paging_state="� Ml�Eޘ��y�����G",page_size=1000,consistency=6,serial_consistency=8}, context: ngx.timer
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called: SELECT * FROM system_schema.columns
  | WHERE keyspace_name = 'kong_dev'
  | AND table_name = 'oauth2_authorization_codes'
  | AND column_name = 'partition' Args Table: nil Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:44 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, created_at, service_id, credential_id, code, authenticated_userid, scope FROM oauth2_authorization_codes WHERE service_id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {page_size=100,consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:45 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called: SELECT * FROM system_schema.columns
  | WHERE keyspace_name = 'kong_dev'
  | AND table_name = 'oauth2_tokens'
  | AND column_name = 'partition' Args Table: nil Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:45 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:       SELECT id, created_at, service_id, credential_id, token_type, expires_in, access_token, refresh_token, authenticated_userid, scope FROM oauth2_tokens WHERE service_id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {page_size=100,consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:45 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called: SELECT * FROM system_schema.columns
  | WHERE keyspace_name = 'kong_dev'
  | AND table_name = 'services'
  | AND column_name = 'partition' Args Table: nil Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:45 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:         SELECT id, created_at, updated_at, name, retries, protocol, host, port, path, connect_timeout, write_timeout, read_timeout, tags FROM services WHERE partition = 'services' AND id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"
  | 2019/07/03 06:02:45 [error] 41#0: *24857 [lua] init.lua:551: execute(): Regular Query called:         DELETE FROM services WHERE partition = 'services' AND id = ?
  | Args Table: {{__cql_type=12,val="2981abc1-8c87-4030-bc1e-b7c9600da0dc"}} Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/2981abc1-8c87-4030-bc1e-b7c9600da0dc HTTP/1.1", host: "localhost:8001"

Was hunting around for the INSERT statements too, seems my logging is only capturing the plugin insert calls as I only see this printing when my chaos builder loop runs:

2019/07/03 06:02:51 [error] 41#0: *24687 [lua] init.lua:551: execute(): Regular Query called:       INSERT INTO plugins (id, name, created_at, route_id, service_id, consumer_id, config, run_on, protocols, enabled, tags, cache_key) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) IF NOT EXISTS
--
  | Args Table: {{__cql_type=12,val="5447c56f-3682-48e8-8342-76ea6fbe822e"},{__cql_type=10,val="acl"},{__cql_type=11,val=1562133771000},{__cql_type=12,val="753121a9-b30b-4051-ab83-7f73df970e48"},{},{},{__cql_type=10,val='{"hide_groups_header":true,"blacklist":null,"whitelist":["753121a9-b30b-4051-ab83-7f73df970e48"]}'},{__cql_type=10,val="first"},{__cql_type=34,val={{__cql_type=10,val="http"},{__cql_type=10,val="https"}}},{__cql_type=4,val=true},{},{__cql_type=10,val="plugins:acl:753121a9-b30b-4051-ab83-7f73df970e48:::"}} Options Table: {consistency=6,serial_consistency=8}, client: 127.0.0.1, server: kong_admin, request: "POST /routes/753121a9-b30b-4051-ab83-7f73df970e48/plugins HTTP/1.1", host: "localhost:8001"

Kinda curious why no routes/service insert calls show up in the logs.

Open to other ideas to try as well, figured grabbing the c* calls would be a good start. Time for 😴 .

jeremyjpj0916 commented 5 years ago

@bungle I tried your PR for the cascade delete 1000 as page size. Still agree would be good to have uniform paging set to 1000 or so across kong globally vs say 100 regardless if it had helped what I was seeing, but no dice. Sadly did not fix the delete service call from eventually bugging out in the tear down portion of my chaos loop which has been the current issue. Appreciate the quick PR attempt though to play with!

Edit - Also setup a JIRA bug report to Apache for the NPE, no clue what will become of it https://issues.apache.org/jira/browse/CASSANDRA-15199

bungle commented 5 years ago

@jeremyjpj0916, yes, I don't expect the issue go away totally, it should just make cascade deletion a bit faster. The 1000 vs 100 is harder to solve. 100 was selected as we wanted admin api to give you 100 entities per page. Now this obviously not a good default for other use cases. E.g. the each should really default to 1000. Perhaps change it so that page and page_for_* defaults to 100 and each defaults to 1000.

jeremyjpj0916 commented 5 years ago

Gotcha thanks for the feedback.

So far apache folk have now responded once: https://issues.apache.org/jira/browse/CASSANDRA-15199?focusedCommentId=16878488&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-16878488

Just for reference, the stacktrace from the Kong issue. Looks like the PagingState contains a null partition key, so potentially an issue with the lua client, but I seem to recall seeing some similar stacktraces when looking into paging issues in mixed version (2.1/3.0) clusters during upgrades.

jeremyjpj0916 commented 5 years ago

But my cluster is also not mixed versions or "in progress" of upgrading. All nodes are running same version.

Trying to get an idea into how paging works in C* I came to here:

https://stackoverflow.com/questions/26757287/results-pagination-in-cassandra-cql and here https://stackoverflow.com/questions/49075702/cassandra-pagination-and-token-function-selecting-a-partition-key

I am trying to think of next steps as I highly doubt this issue gets reproduced easily on Kongs side in a vacuum. Maybe easier for me to adjust the logging to capture the state of things when the C problem occurs(as opposed to just logging all C calls like I did above which came with a lot of noise and I can't pinpoint anything too interesting up there when the failure occured), specifically information around the paging_state and any partition key in use may be helpful?

Another diagram I liked that explains the C* paging improvements too at bottom: https://www.datastax.com/dev/blog/client-side-improvements-in-cassandra-2-0

I see the lua driver has some details around paging state and partition keys here: https://github.com/thibaultcha/lua-cassandra/blob/2fe82cc884a7022050c18de9187a9d0a7d4517ef/lib/cassandra/cql.lua#L1274

jeremyjpj0916 commented 5 years ago

Slight update here today. Did some sanity checking against our current stage(I took a stage env and bloated it with 3,050 proxies/consumers and such) instances of Kong running 1.0.3 with a few custom mods @bungle wrote up long ago when we had some issues around route/plugin rebuilds. Using the same chaos test of standing resources up and tearing them down I was unable to reproduce the cascade delete call on 1.0.3, I let it iterate 75 times on stand up and tear down. On 1.2 I always reproduce the C* issue within the first 30 loops of stand up and tear down.

Those Bungle modded Kong files on 1.0.3 are attached as follows: /usr/local/share/lua/5.1/kong/runloop/handler.lua

handler.txt

/usr/local/share/lua/5.1/kong/init.lua

init.txt

Thing is I don't see how those files would make the difference in say the Admin API Delete call that fails in 1.2 occasionally. So I am thinking I might be able to do a diff on some of the files in 1.0.3 and in 1.2 and see if anything stands out in a hot path somewhere in the LUA around these C calls . If you have any files you want me to diff that would bring the most interest let me know @bungle or @thibaultcha but I will start with some C driver and Kong side files that I have been using for debugging lately.

As always open to other test ideas too.

jeremyjpj0916 commented 5 years ago

Well internally our goal is to move forward regardless to try and keep up with newer Kong versions even though we have been unable to nail down a patch/fix for what we see.

I am now testing on 1.2.1 (as this will be what we move to from 1.0.3 where everything was stable for us with the custom bungle mods). Decided to tear down(delete) those 3000+ resources. Can note during the tear down delete of the route/service/consumer accounts that the consumer resources had no issues deleting they all cleared out first try. I had to run the script multiple times before the routes/services all cleared out though. And even when they were all cleared out, it seems that 30ish plugins(that were tied to various route resources) still persisted on lookup with no route that actually existed underlying to it. Meaning that when I did a delete on some of the route resources somehow the plugins tied to that route must have not actually deleted which is interesting.

I decided to do one last test where I reduced the resources back under 100 proxies and am now testing the chaos create + delete again as well to see if the issue of failed deletion of the service presented itself again, and it did not after 75+ iteration attempts of standing up the proxy and tearing it down. So that affirms the suspicion even more that paging has something to do with the issues I can produce.

We are likely going to add some retry logic in our automation to try to get around the occasional paging issues on delete hopefully until it gets fixed somewhere down the road. We will also be running the sticky persistance against C* we made in the concurrency.lua file for router/plugin map rebuilds.

jeremyjpj0916 commented 5 years ago

(UPDATE: Solved this unrelated bit to the actual issue at hand, read at peril of your time or for your own amusement at my crazy ramblings)

Well slight problem in my approach to go to Kong 1.2.1 with the concurrency.lua db keepalive adjustment I am finding out now... By doing this in concurrency.lua (which at least kept my router/plugin map rebuilds w paging working fine) I now have issues with kong migrations up || finish because kong.db is considered nil in those situations(besides the kong start runtime) 💀 . Sadly did not find this out because originally when debugging I didn't mess with concurrency.lua to make things work until after all the migrations up || finish stuff had been ran 😆 :

Error:
/usr/local/share/lua/5.1/kong/concurrency.lua:47: attempt to index field 'db' (a nil value)
stack traceback:
        /usr/local/share/lua/5.1/kong/concurrency.lua:47: in function 'cluster_mutex'
        /usr/local/share/lua/5.1/kong/cmd/utils/migrations.lua:197: in function 'finish'
        /usr/local/share/lua/5.1/kong/cmd/migrations.lua:209: in function 'cmd_exec'
        /usr/local/share/lua/5.1/kong/cmd/init.lua:87: in function </usr/local/share/lua/5.1/kong/cmd/init.lua:87>
        [C]: in function 'xpcall'
        /usr/local/share/lua/5.1/kong/cmd/init.lua:87: in function </usr/local/share/lua/5.1/kong/cmd/init.lua:44>
        /usr/bin/kong:7: in function 'file_gen'
        init_worker_by_lua:48: in function <init_worker_by_lua:46>
        [C]: in function 'xpcall'
        init_worker_by_lua:55: in function <init_worker_by_lua:53>
local resty_lock = require "resty.lock"
local ngx_semaphore = require "ngx.semaphore"

local get_phase = ngx.get_phase

local concurrency = {}

-- these must remain for the lifetime of the process
local semaphores = {}

function concurrency.with_worker_mutex(opts, fn)
  if type(opts) ~= "table" then
    error("opts must be a table", 2)
  end
  if type(opts.name) ~= "string" then
    error("opts.name is required and must be a string", 2)
  end
  if opts.timeout and type(opts.timeout) ~= "number" then
    error("opts.timeout must be a number", 2)
  end

  local timeout = opts.timeout or 60

  local rlock, err = resty_lock:new("kong_locks", {
    exptime = timeout,
    timeout = timeout,
  })
  if not rlock then
    return nil, "failed to create worker lock: " .. err
  end

  -- acquire lock
  local elapsed, err = rlock:lock(opts.name)
  if not elapsed then
    if err == "timeout" then
      return nil, err
    end
    return nil, "failed to acquire worker lock: " .. err
  end

  local pok, ok, err
  ok, err = kong.db:connect() < ------- REKT RIGHT HERE DURING MIGRATIONS
  if ok then
    pok, ok, err = pcall(fn, elapsed)
    if not pok then
        err = ok
        ok = nil
    end
    kong.db:setkeepalive()
  else
    kong.db:close()
    log(CRIT, "could not connect to the database while rebuilding ", opts.name, " asynchronously:", err)
  end

  -- release lock
  rlock:unlock(opts.name)
  return ok, err
end

function concurrency.with_coroutine_mutex(opts, fn)
  if type(opts) ~= "table" then
    error("opts must be a table", 2)
  end
  if type(opts.name) ~= "string" then
    error("opts.name is required and must be a string", 2)
  end
  if opts.timeout and type(opts.timeout) ~= "number" then
    error("opts.timeout must be a number", 2)
  end
  if opts.on_timeout and
     opts.on_timeout ~= "run_unlocked" and
     opts.on_timeout ~= "return_true" then
    error("invalid value for opts.on_timeout", 2)
  end

  if get_phase() == "init_worker" then
    return fn()
  end

  local timeout = opts.timeout or 60

  local semaphore = semaphores[opts.name]

  -- the following `if` block must not yield:
  if not semaphore then
    local err
    semaphore, err = ngx_semaphore.new()
    if err then
      return nil, "failed to create " .. opts.name .. " lock: " .. err
    end
    semaphores[opts.name] = semaphore

    semaphore:post(1)
  end

  -- acquire lock
  local lok, err = semaphore:wait(timeout)
  if not lok then
    if err ~= "timeout" then
      return nil, "error attempting to acquire " .. opts.name .. " lock: " .. err
    end

    if opts.on_timeout == "run_unlocked" then
      kong.log.warn("bypassing ", opts.name, " lock: timeout")
    elseif opts.on_timeout == "return_true" then
      return true
    else
      return nil, "timeout acquiring " .. opts.name .. " lock"
    end
  end

  local pok, ok, err
  ok, err = kong.db:connect()
  if ok then
    pok, ok, err = pcall(fn)
    if not pok or not ok then
      log(CRIT, "could not rebuild ", opts.name, " asynchronously:", ok or err)
    end
    kong.db:setkeepalive()

  else
    kong.db:close()
    log(CRIT, "could not connect to the database while rebuilding ", opts.name, " asynchronously:", err)
  end

  if lok then
    -- release lock
    semaphore:post(1)
  end

  if not pok then
    return nil, ok
  end

  return ok, err
end

return concurrency

Anyone have a quick and dirty way I can check if db is init here, if not init then initialize it? Or maybe there is another spot I can drop in the init of the db in the migrations path so I can access kong.db within concurrency safely(This is not something normal Kong needs at the moment but it does if I don't want paging to break critical hotpaths for us when we run Kong on newer versions). I will hunt for a way to initialize the db in the meantime so I can use it here.

On the side I think I might not even have any migrations finish necessary because from 1.0.3 to 1.2.1 it seems just doing kong migrations up may have taken care of it all(at least thats how i interpret pending null).

*****@cqlsh:kong_dev> select * from schema_meta;

 key         | subsystem             | executed                                                                        | last_executed  | pending
-------------+-----------------------+---------------------------------------------------------------------------------+----------------+---------
 schema_meta |                   acl |                                                {'000_base_acl', '001_14_to_15'} |   001_14_to_15 |    null
 schema_meta |            basic-auth |                                         {'000_base_basic_auth', '001_14_to_15'} |   001_14_to_15 |    null
 schema_meta |                  core | {'000_base', '001_14_to_15', '002_15_to_1', '003_100_to_110', '004_110_to_120'} | 004_110_to_120 |    null
 schema_meta |             hmac-auth |                                          {'000_base_hmac_auth', '001_14_to_15'} |   001_14_to_15 |    null
 schema_meta |                   jwt |                                                {'000_base_jwt', '001_14_to_15'} |   001_14_to_15 |    null
 schema_meta |              key-auth |                                           {'000_base_key_auth', '001_14_to_15'} |   001_14_to_15 |    null
 schema_meta |                oauth2 |                             {'000_base_oauth2', '001_14_to_15', '002_15_to_10'} |   002_15_to_10 |    null
 schema_meta |         rate-limiting |     {'000_base_rate_limiting', '001_14_to_15', '002_15_to_10', '003_10_to_112'} |  003_10_to_112 |    null
 schema_meta | response-ratelimiting |             {'000_base_response_rate_limiting', '001_14_to_15', '002_15_to_10'} |   002_15_to_10 |    null

Although I am sure you all would tell me not assume that and I should always finish a migrations up with migrations finish when ready to switch over to new kong iteration 😀 .

Final Edit- Oh duhhh I just answered my own question thinking about it more:

I can just do something like 

if kong.db then
-- Do the whacky db keepalive so Kong works for us
else
-- Do the standard execution of concurrency.lua without db keepalive
end

BINGO!!!!

jeremyjpj0916 commented 5 years ago

I wonder.. if some of the revelations around the cluster_events table being too full of tombstones potentially to read may play a role here: https://github.com/Kong/kong/issues/4849 .. just a before bed thought, could be way off base but MAYBE thats why kong side had so much trouble reproducing what I was seeing with the page errors.

jeremyjpj0916 commented 5 years ago

Confirmed still occurring on 1.3(note: still running the concurrent.lua file with a db keepalive patch so router/plugins mapper rebuilds don't face similar rebuild issues), didn't really expect it to go away based on changes thus far.

Testing was like so: Just had a dev sandbox running 50 proxy resources or so, no issues there chaos create + deleting.

Ramped it up to 3,050 consumers and proxies(service+route+plugins on route) and doing create + deletes.

Saw a few admin API GETS failed + the usual DELETE fail: 

2019/08/26 06:28:54 [error] 28#0: *3514372 [kong] kong.lua:45 [cassandra] could not execute page query: [Server error] java.lang.NullPointerException, client: 10.129.28.1, server: kong_admin, request: "GET / HTTP/1.1", host: "kong:8001"

2019/08/26 06:52:19 [error] 28#0: *3585189 [kong] init.lua:98 could not execute page query: [Server error] java.lang.NullPointerException, client: 10.129.28.1, server: kong_admin, request: "GET /consumers?offset=EEu958Pc8kDaqf9LixmjW3YA8H%2F%2F%2BusA HTTP/1.1", host: "kong:8001"

2019/08/26 07:22:35 [error] 29#0: *3675201 [kong] kong.lua:45 [cassandra] could not execute page query: [Server error] java.lang.NullPointerException, client: 10.129.28.1, server: kong_admin, request: "GET / HTTP/1.1", host: "kong:8001"

2019/08/26 07:30:08 [error] 28#0: *3683693 [kong] init.lua:98 could not gather associated entities for delete cascade: [cassandra] could not execute page query: [Server error] java.lang.NullPointerException, client: 127.0.0.1, server: kong_admin, request: "DELETE /services/50e56a73-cfa5-4cf6-92dd-c8eb23da252f HTTP/1.1", host: "localhost:8001"

One of the interesting bits of those NPE responses from C* there on just the base GET / of the kong admin path? So those were not even paging calls causing those it seems. Still odd 1.0.3 with the bungle PRs long back fixed these sorta issues and most of those enhancements were merged in. I suppose what was not incorporated into the flagship was what added some of the extra stability, but maybe had potential to be detrimental outside our scope.

bungle commented 4 years ago

@jeremyjpj0916, yes we got almost everything in, except those connect calls. The Admin API GET / does btw. kong.db.plugins:each(), so it seems like a generic issue there. I think you just cannot perhaps trust Cassandra when paging that may end up in different node than the previous page OR you need to execute them with QUORUM? Then I am not sure which one is better.

jeremyjpj0916 commented 4 years ago

@bungle ah you came back to an oldie issue 😀 , its still relevant today I believe(haven't had time to dig into this in awhile) but its fairly infrequent(always took somewhere around 25+ calls of things in a row within a loop with a 1-5 second pause between ops) so we don't see it in the wild with self-service yet really which are spread out operations generally. And we do run with KONG_CASSANDRA_CONSISTENCY: LOCAL_QUORUM (and I would always stick to using the admin API against one datacenter for my CRUD ops in my tests) with a KONG_CASSANDRA_LB_POLICY: RequestDCAwareRoundRobin . So this has kinda just stayed a low priority in the back of my mind, because besides this issue there is really very little I can spot these days I consider buggy with Kong which is a good thing(well there is also TLS connection management I remember Tibo was gonna dig into on the OpenResty/Kong side too at some point, PR still pending to OpenResty I beleive)!

We are working on doing Mutual TLS internally w clients -> Kong right now, which is requiring us to solve things like WAF at NGINX layer(can't have TLS re-encrypting w a WAF at our load balancers anymore, been looking into ModSec v3 w Nginx connector, seems promising! Would be neat if Kong ever endorsed integrations with open source waf tooling and slimmed a rulset ideal for api gateway security) and a bunch of other ideas around management of the client certs and truststores etc. So that is eating up a lot of my time. Will likely post about my findings on the Discuss Kong forum sometime when I have concrete findings.

Supposedly that Scalla DB now has lightweight tx and can support Kong I believe, so might be worth checking out one day if their solution in C runs into the same issues we have seen in Cassandra.

bungle commented 4 years ago

@jeremyjpj0916,

I am glad to report that this was finally chased down by @vasuharish. Please let us know if you still see issues after applying #5564.

jeremyjpj0916 commented 4 years ago

@bungle this is big news! Super excited someone got to the bottom of it and it wasn't even Kong core team contributing the fix this time. Power of open source hah.

I suppose I can finally remove the janky hack I did to to the Kong concurreny.lua file as well that helped bandaid some stability in prior to this guys new PR?

image

Seems like the new PR would fix the root cause this little hack helped with I have been using you gave me about a year ago.