Error when fetching consumer details on 0.9.3

[kkindaface]

Summary

http://localhost:8001/consumers/aa49f0e6-a3f9-44c1-8e17-15a6e19eb37b/oauth2?client_id=TestClient

returns an http 500 and I see the following in error.log

stack traceback:
[C]: in function 'error'
/usr/local/share/lua/5.1/lapis/application.lua:396: in function 'handler'
/usr/local/share/lua/5.1/lapis/application.lua:130: in function 'resolve'
/usr/local/share/lua/5.1/kong/api/init.lua:50: in function 'handler'
/usr/local/share/lua/5.1/lapis/application.lua:130: in function 'handler'
/usr/local/share/lua/5.1/lapis/application.lua:163: in function </usr/local/share/lua/5.1/lapis/application.lua:159>
[C]: in function 'xpcall'
/usr/local/share/lua/5.1/lapis/application.lua:159: in function 'dispatch'
/usr/local/share/lua/5.1/lapis/nginx.lua:214: in function 'serve'
content_by_lua(nginx-kong.conf:111):10: in function <content_by_lua(nginx-kong.conf:111):1>, client: 127.0.0.1, server: kong_admin, request: "GET /consumers/aa49f0e6-a3f9-44c1-8e17-15a6e19eb37b/oauth2?client_id=TestClient HTTP/1.1", host: "localhost:8001"

• Kong version 0.9.3
• Kong debug-level startup logs ($ kong start --vv)

2016/10/11 16:09:32 [verbose] Kong: 0.9.3
2016/10/11 16:09:32 [debug] ngx_lua: 10005
2016/10/11 16:09:32 [debug] nginx: 1009015
2016/10/11 16:09:32 [debug] Lua: LuaJIT 2.1.0-beta2
2016/10/11 16:09:32 [verbose] no config file found at /etc/kong.conf
2016/10/11 16:09:32 [verbose] reading config file at /etc/kong/kong.conf
2016/10/11 16:09:32 [debug] admin_listen = "0.0.0.0:8001"
2016/10/11 16:09:32 [debug] anonymous_reports = true
2016/10/11 16:09:32 [debug] cassandra_consistency = "ONE"
2016/10/11 16:09:32 [debug] cassandra_contact_points = {"127.0.0.1"}
2016/10/11 16:09:32 [debug] cassandra_data_centers = {"dc1:2","dc2:3"}
2016/10/11 16:09:32 [debug] cassandra_keyspace = "kong"
2016/10/11 16:09:32 [debug] cassandra_port = 9042
2016/10/11 16:09:32 [debug] cassandra_repl_factor = 1
2016/10/11 16:09:32 [debug] cassandra_repl_strategy = "SimpleStrategy"
2016/10/11 16:09:32 [debug] cassandra_ssl = false
2016/10/11 16:09:32 [debug] cassandra_ssl_verify = false
2016/10/11 16:09:32 [debug] cassandra_timeout = 5000
2016/10/11 16:09:32 [debug] cassandra_username = "kong"
2016/10/11 16:09:32 [debug] cluster_listen = "0.0.0.0:7946"
2016/10/11 16:09:32 [debug] cluster_listen_rpc = "127.0.0.1:7373"
2016/10/11 16:09:32 [debug] cluster_profile = "wan"
2016/10/11 16:09:32 [debug] cluster_ttl_on_failure = 3600
2016/10/11 16:09:32 [debug] custom_plugins = {}
2016/10/11 16:09:32 [debug] database = "postgres"
2016/10/11 16:09:32 [debug] dns_resolver = "8.8.8.8"
2016/10/11 16:09:32 [debug] dnsmasq = false
2016/10/11 16:09:32 [debug] dnsmasq_port = 8053
2016/10/11 16:09:32 [debug] log_level = "notice"
2016/10/11 16:09:32 [debug] lua_code_cache = "on"
2016/10/11 16:09:32 [debug] lua_package_cpath = ""
2016/10/11 16:09:32 [debug] lua_package_path = "?/init.lua;./kong/?.lua"
2016/10/11 16:09:32 [debug] lua_ssl_verify_depth = 1
2016/10/11 16:09:32 [debug] mem_cache_size = "128m"
2016/10/11 16:09:32 [debug] nginx_daemon = "on"
2016/10/11 16:09:32 [debug] nginx_optimizations = true
2016/10/11 16:09:32 [debug] nginx_worker_processes = "auto"
2016/10/11 16:09:32 [debug] pg_database = "kong"
2016/10/11 16:09:32 [debug] pg_host = "127.0.0.1"
2016/10/11 16:09:32 [debug] pg_password = "******"
2016/10/11 16:09:32 [debug] pg_port = 5432
2016/10/11 16:09:32 [debug] pg_ssl = false
2016/10/11 16:09:32 [debug] pg_ssl_verify = false
2016/10/11 16:09:32 [debug] pg_user = "postgres"
2016/10/11 16:09:32 [debug] prefix = "/usr/local/kong/"
2016/10/11 16:09:32 [debug] proxy_listen = "0.0.0.0:8000"
2016/10/11 16:09:32 [debug] proxy_listen_ssl = "0.0.0.0:8443"
2016/10/11 16:09:32 [debug] serf_path = "serf"
2016/10/11 16:09:32 [debug] ssl = true
2016/10/11 16:09:32 [verbose] prefix in use: /usr/local/kong
2016/10/11 16:09:32 [verbose] preparing nginx prefix directory at /usr/local/kong
2016/10/11 16:09:32 [verbose] saving serf identifier to /usr/local/kong/serf/serf.id
2016/10/11 16:09:32 [debug] searching for OpenResty 'resty' executable
2016/10/11 16:09:32 [debug] /usr/local/openresty/bin/resty -V: 'nginx version: openresty/1.9.15.1'
2016/10/11 16:09:32 [debug] found OpenResty 'resty' executable at /usr/local/openresty/bin/resty
2016/10/11 16:09:32 [verbose] saving serf shell script handler to /usr/local/kong/serf/serf_event.sh
2016/10/11 16:09:32 [verbose] SSL enabled, no custom certificate set: using default certificate
2016/10/11 16:09:32 [verbose] default SSL certificate found at /usr/local/kong/ssl/kong-default.crt
2016/10/11 16:09:32 [warn] ulimit is currently set to "2560". For better performance set it to at least "4096" using "ulimit -n"
2016/10/11 16:09:32 [verbose] running datastore migrations
2016/10/11 16:09:32 [verbose] migrations up to date
2016/10/11 16:09:32 [verbose] serf agent not running, deleting /usr/local/kong/pids/serf.pid
2016/10/11 16:09:32 [debug] checking 'serf' executable from 'serf_path' config setting
2016/10/11 16:09:32 [debug] serf version: 'Serf v0.7.0'
2016/10/11 16:09:32 [debug] starting serf agent: nohup serf agent -profile 'wan' -rpc-addr '127.0.0.1:7373' -event-handler 'member-join,member-leave,member-failed,member-update,member-reap,user:kong=/usr/local/kong/serf/serf_event.sh' -bind '0.0.0.0:7946' -node 'C02QWCMXG8WN_0.0.0.0:7946_465a78ad93cc432ea8369824d49506d6' -log-level 'err' > /usr/local/kong/logs/serf.log 2>&1 & echo $! > /usr/local/kong/pids/serf.pid
2016/10/11 16:09:32 [verbose] waiting for serf agent to be running
2016/10/11 16:09:32 [debug] sending signal to pid at: /usr/local/kong/pids/serf.pid
2016/10/11 16:09:32 [debug] kill -0 cat /usr/local/kong/pids/serf.pid >/dev/null 2>&1
2016/10/11 16:09:32 [verbose] serf agent started
2016/10/11 16:09:32 [verbose] auto-joining serf cluster
2016/10/11 16:09:32 [verbose] no other nodes found in the cluster
2016/10/11 16:09:32 [verbose] registering serf node in datastore
2016/10/11 16:09:32 [verbose] cluster joined and node registered in datastore
2016/10/11 16:09:32 [debug] searching for OpenResty 'nginx' executable
2016/10/11 16:09:32 [debug] /usr/local/openresty/nginx/sbin/nginx -v: 'nginx version: openresty/1.9.15.1'
2016/10/11 16:09:32 [debug] found OpenResty 'nginx' executable at /usr/local/openresty/nginx/sbin/nginx
2016/10/11 16:09:32 [debug] starting nginx: /usr/local/openresty/nginx/sbin/nginx -p /usr/local/kong -c nginx.conf
2016/10/11 16:09:33 [debug] nginx started
2016/10/11 16:09:33 [info] Kong started

• Operating System: Mac OSX 10.11.6

[kkindaface]

Here is the complete error I see in error.log

2016/10/11 16:38:14 [error] 97471#0: *229 lua coroutine: runtime error: /usr/local/share/lua/5.1/kong/dao/postgres_db.lua:216: Expected value but found invalid token at character 1
stack traceback:
coroutine 0:
[C]: in function 'decode'
/usr/local/share/lua/5.1/kong/dao/postgres_db.lua:216: in function 'deserialize_rows'
/usr/local/share/lua/5.1/kong/dao/postgres_db.lua:157: in function 'query'
/usr/local/share/lua/5.1/kong/dao/postgres_db.lua:383: in function 'find_page'
/usr/local/share/lua/5.1/kong/dao/dao.lua:198: in function 'find_page'
/usr/local/share/lua/5.1/kong/api/crud_helpers.lua:53: in function 'paginated_set'
/usr/local/share/lua/5.1/kong/plugins/oauth2/api.lua:63: in function </usr/local/share/lua/5.1/kong/plugins/oauth2/api.lua:62>
coroutine 1:
[C]: in function 'resume'
/usr/local/share/lua/5.1/lapis/application.lua:393: in function 'handler'
/usr/local/share/lua/5.1/lapis/application.lua:130: in function 'resolve'
/usr/local/share/lua/5.1/kong/api/init.lua:50: in function 'handler'
/usr/local/share/lua/5.1/lapis/application.lua:130: in function 'handler'
/usr/local/share/lua/5.1/lapis/application.lua:163: in function </usr/local/share/lua/5.1/lapis/application.lua:159>
[C]: in function 'xpcall'
/usr/local/share/lua/5.1/lapis/application.lua:159: in function 'dispatch'
/usr/local/share/lua/5.1/lapis/nginx.lua:214: in function 'serve'
content_by_lua(nginx-kong.conf:111):10: in function <content_by_lua(nginx-kong.conf:111):1>, client: 127.0.0.1, server: kong_admin, request: "GET /consumers/aa49f0e6-a3f9-44c1-8e17-15a6e19eb37b/oauth2?client_id=TestClient HTTP/1.1", host: "localhost:8001"
2016/10/11 16:38:14 [error] 97471#0: *229 [lua] init.lua:62: handle_error(): /usr/local/share/lua/5.1/lapis/application.lua:396: /usr/local/share/lua/5.1/kong/dao/postgres_db.lua:216: Expected value but found invalid token at character 1
stack traceback:
[C]: in function 'decode'
/usr/local/share/lua/5.1/kong/dao/postgres_db.lua:216: in function 'deserialize_rows'
/usr/local/share/lua/5.1/kong/dao/postgres_db.lua:157: in function 'query'
/usr/local/share/lua/5.1/kong/dao/postgres_db.lua:383: in function 'find_page'
/usr/local/share/lua/5.1/kong/dao/dao.lua:198: in function 'find_page'
/usr/local/share/lua/5.1/kong/api/crud_helpers.lua:53: in function 'paginated_set'
/usr/local/share/lua/5.1/kong/plugins/oauth2/api.lua:63: in function </usr/local/share/lua/5.1/kong/plugins/oauth2/api.lua:62>

stack traceback:
[C]: in function 'error'
/usr/local/share/lua/5.1/lapis/application.lua:396: in function 'handler'
/usr/local/share/lua/5.1/lapis/application.lua:130: in function 'resolve'
/usr/local/share/lua/5.1/kong/api/init.lua:50: in function 'handler'
/usr/local/share/lua/5.1/lapis/application.lua:130: in function 'handler'
/usr/local/share/lua/5.1/lapis/application.lua:163: in function </usr/local/share/lua/5.1/lapis/application.lua:159>
[C]: in function 'xpcall'
/usr/local/share/lua/5.1/lapis/application.lua:159: in function 'dispatch'
/usr/local/share/lua/5.1/lapis/nginx.lua:214: in function 'serve'
content_by_lua(nginx-kong.conf:111):10: in function <content_by_lua(nginx-kong.conf:111):1>, client: 127.0.0.1, server: kong_admin, request: "GET /consumers/aa49f0e6-a3f9-44c1-8e17-15a6e19eb37b/oauth2?client_id=TestClient HTTP/1.1", host: "localhost:8001"

[kkindaface]

This seems to be happening because of the redirect_uri being changed to an array. I manually changed the redirect_uri in the postgres DB and put it inside [" "] and it started returning the consumer details as usual. Is there a step that I could have missed during the upgrade from 0.8.1 to 0.9.3?

[DonMartin76]

I just know the representation of the redirect_uri on the oauth2 consumer plugin was encoded as a JSON array inside a JSON string before, and now it's an explicit array. This was a change which was done between 0.8.3 and 0.9.2 (or possibly 0.9.0 or 0.9.1).

Before:

"redirect_uri":"[\"http:\/\/dummy.org\"]"

After:

"redirect_uri":["http://dummy.org"]

I assume this is/should be updated in some migration step inside Kong.

[kkindaface]

Yes, thats correct. I just took a look inside the kong migration scripts for cassandra and postgres. Looks like the script "2016-04-14-283949_serialize_redirect_uri" is not being run for postgres. It exists only inside cassandra.lua

[thibaultcha]

Thanks for reporting and tracking this down. This would seem to be the reason why indeed! Now I'll have to investigate if by adding the missing migration in the postgres migrations, we will indeed execute that migration (in a future bugfix release), or not... which would be quite painful to fix.