We are doing some testing of the Kong HTTP log plugin, found out a Kong read and connection timeouts does not invoke the HTTP log plugin in the process for any valuable information. Is there a reason for that or a way to make it so the Http log plugin could send out relevant info?
I’d like to be able to see what specific error occurred too if possible.
I am working alongside Ross, and just wanted to add to this a tad with some screenshots. Proxy definition to enforce a read timeout(“upstream_read_timeout”) we set this property to 1 millisecond to force a failure:
And the Kong response behavior to the Proxy Consumer:
And so far transactions using the http-log plugin show none of this ever occurring. Now the proxy error logs do currently print to std-out, but would you agree that tcp/udp/http-log and all the rest are within the scope of documenting these sorts of errors as well? And if not, then could you guide us as to how we might branch the http-log plugin so it can log these transactions as well? Note that we are indeed also running the Kong 0.12.1 version that has this sort of short circuiting fix in place for transactions that were rejected with a 401 unauthorized (and can confirm indeed the plugins do receive logs in those cases for that fix!).
Thanks for your time and consideration,
-Jeremy
Hi,
Indeed, a timeout from the ngx_http_proxy_module will make NGINX produce an HTTP 504 response, which the error_page directive in the Kong NGINX configuration will catch and redirect to our upstream error handling internal NGINX location. This location does not run anything in the NGX_HTTP_LOG_PHASE.
A simple fix for this would be:
diff --git a/kong/templates/nginx_kong.lua b/kong/templates/nginx_kong.lua
index 5639f319..61b3d87f 100644
--- a/kong/templates/nginx_kong.lua
+++ b/kong/templates/nginx_kong.lua
@@ -147,6 +147,10 @@ server {
content_by_lua_block {
kong.handle_error()
}
+
+ log_by_lua_block {
+ kong.log()
+ }
}
}
Thanks man! Is this something you think should be added into baseline Kong or do we need to deviate from the norm here and bite the bullet and make a custom template?
Just to explain from our perspective:
We get in a meeting where consumer is having an error, support reviews http-logs we fwd to splunk trying to find the transaction in question. Since Kong shortcuts on these cases a tech would find no trace of these transactions in splunk. Timeouts can be a pretty common occurrence when backend APIs rely on systems that get extremely sluggish at random times of stress 
.
-Jeremy
This should be a part of Kong. Contributions welcome!
Hi can we expect this in 0.12.2? Thanks!
Hi All!
We gave this a shot, and unfortunately it didn’t seem to work. Here’s our current nginx-kong.conf file, do you see anything wrong?
charset UTF-8;
error_log /dev/stderr notice;
client_max_body_size 0;
proxy_ssl_server_name on;
underscores_in_headers on;
lua_package_path './?.lua;./?/init.lua;;;';
lua_package_cpath ';;';
lua_socket_pool_size 30;
lua_max_running_timers 4096;
lua_max_pending_timers 16384;
lua_shared_dict kong 5m;
lua_shared_dict kong_cache 256m;
lua_shared_dict kong_process_events 5m;
lua_shared_dict kong_cluster_events 5m;
lua_shared_dict kong_healthchecks 5m;
lua_shared_dict kong_cassandra 5m;
lua_socket_log_errors off;
lua_ssl_trusted_certificate '/usr/local/kong/ssl/kongcert.pem';
lua_ssl_verify_depth 2;
init_by_lua_block {
kong = require 'kong'
kong.init()
}
init_worker_by_lua_block {
kong.init_worker()
}
proxy_next_upstream_tries 999;
upstream kong_upstream {
server 0.0.0.1;
balancer_by_lua_block {
kong.balancer()
}
keepalive 60;
}
server {
server_name kong;
listen 0.0.0.0:8000;
error_page 400 404 408 411 412 413 414 417 /kong_error_handler;
client_header_buffer_size 8k;
large_client_header_buffers 100 32k;
error_page 500 502 503 504 /kong_error_handler;
access_log off;
error_log /dev/stderr notice;
client_body_buffer_size 5m;
listen 0.0.0.0:8443 ssl http2;
ssl_certificate /usr/local/kong/ssl/kongcert.crt;
ssl_certificate_key /usr/local/kong/ssl/kongprivatekey.key;
ssl_protocols TLSv1.2;
ssl_certificate_by_lua_block {
kong.ssl_certificate()
}
ssl_session_cache shared:SSL:10m;
ssl_session_timeout 10m;
ssl_prefer_server_ciphers on;
ssl_ciphers ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256;
real_ip_header X-Real-IP;
real_ip_recursive off;
location / {
set $upstream_host '';
set $upstream_upgrade '';
set $upstream_connection '';
set $upstream_scheme '';
set $upstream_uri '';
set $upstream_x_forwarded_for '';
set $upstream_x_forwarded_proto '';
set $upstream_x_forwarded_host '';
set $upstream_x_forwarded_port '';
rewrite_by_lua_block {
kong.rewrite()
}
access_by_lua_block {
kong.access()
}
proxy_http_version 1.1;
proxy_set_header Host $upstream_host;
proxy_set_header Upgrade $upstream_upgrade;
proxy_set_header Connection $upstream_connection;
proxy_set_header X-Forwarded-For $upstream_x_forwarded_for;
proxy_set_header X-Forwarded-Proto $upstream_x_forwarded_proto;
proxy_set_header X-Forwarded-Host $upstream_x_forwarded_host;
proxy_set_header X-Forwarded-Port $upstream_x_forwarded_port;
proxy_set_header X-Real-IP $remote_addr;
proxy_pass_header Server;
proxy_pass_header Date;
proxy_ssl_name $upstream_host;
proxy_pass $upstream_scheme://kong_upstream$upstream_uri;
header_filter_by_lua_block {
kong.header_filter()
}
body_filter_by_lua_block {
kong.body_filter()
}
log_by_lua_block {
kong.log()
}
}
location = /kong_error_handler {
internal;
content_by_lua_block {
kong.handle_error()
}
log_by_lua_block {
kong.log()
}
}
}
server {
server_name kong_admin;
listen 0.0.0.0:8001;
access_log off;
error_log /dev/stderr notice;
client_max_body_size 10m;
client_body_buffer_size 10m;
listen 0.0.0.0:8444 ssl;
ssl_certificate /usr/local/kong/ssl/admin-kong-default.crt;
ssl_certificate_key /usr/local/kong/ssl/admin-kong-default.key;
ssl_protocols TLSv1.2;
ssl_session_cache shared:SSL:10m;
ssl_session_timeout 10m;
ssl_prefer_server_ciphers on;
ssl_ciphers ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256;
location / {
default_type application/json;
content_by_lua_block {
kong.serve_admin_api()
}
}
location /nginx_status {
allow 127.0.0.1;
deny all;
access_log off;
stub_status;
}
location /robots.txt {
return 200 'User-agent: *\nDisallow: /';
}
}
To add to Ross point above I thought it worthwhile to give some insight into our Dockerfile too as that is how we make the modifications to the lua template files kong includes rather than writing our own(for the time being):
FROM docker.company.com/company_et/alpine:3.6
ENV KONG_VERSION 0.12.1
ENV KONG_SHA256 9f699e20e7d3aa6906b14d6b52cae9996995d595d646f9b10ce09c61d91a4257
USER root
RUN apk add --no-cache --virtual .build-deps wget tar ca-certificates \
&& apk add --no-cache libgcc openssl pcre perl unzip tzdata luarocks git \
&& wget -O kong.tar.gz "https://bintray.com/kong/kong-community-edition-alpine-tar/download_file?file_path=kong-community-edition-$KONG_VERSION.apk.tar.gz" \
&& echo "$KONG_SHA256 *kong.tar.gz" | sha256sum -c - \
&& tar -xzf kong.tar.gz -C /tmp \
&& rm -f kong.tar.gz \
&& cp -R /tmp/usr / \
&& rm -rf /tmp/usr \
&& cp -R /tmp/etc / \
&& rm -rf /tmp/etc \
&& apk del .build-deps
RUN mkdir /usr/local/kong
COPY docker-entrypoint.sh /docker-entrypoint.sh
#Rewrite nginx kong conf to only enable TLS1.2
RUN sed -i '/ssl_protocols TLSv1.1 TLSv1.2;/c\ ssl_protocols TLSv1.2;' /usr/local/share/lua/5.1/kong/templates/nginx_kong.lua
#Temporary fix attempt to log timeouts
RUN sed -ie '/kong.handle_error()/{n;d}' /usr/local/share/lua/5.1/kong/templates/nginx_kong.lua; sed -i '/kong.handle_error()/ a \\t}\n\n\tlog_by_lua_block {\n\t\tkong.log()\n\t}' /usr/local/share/lua/5.1/kong/templates/nginx_kong.lua
#Increase the buffer header defaults
RUN sed -i '68i client_header_buffer_size 8k;' /usr/local/share/lua/5.1/kong/templates/nginx_kong.lua
RUN sed -i '69i large_client_header_buffers 100 32k;' /usr/local/share/lua/5.1/kong/templates/nginx_kong.lua
#Rewrite ngix conf so we can see our Kong ENV variable
RUN sed -i '8ienv KONG_SSL_CERT_KEY;' /usr/local/share/lua/5.1/kong/templates/nginx.lua
#Install custom plugins with luarocks
RUN luarocks install kong-plugin-stdout-log
RUN luarocks install kong-upstream-jwt
#Install HTTP plugin
RUN git clone https://github.optum.com/DataExternalization/optum-kong-http-log-plugin.git /usr/local/share/lua/5.1/kong/plugins/optum-kong-http-log-plugin
ENTRYPOINT ["/docker-entrypoint.sh"]
EXPOSE 8000 8443 8001 8444
STOPSIGNAL SIGTERM
USER 1001
CMD ["/usr/local/openresty/nginx/sbin/nginx", "-c", "/usr/local/kong/nginx.conf", "-p", "/usr/local/kong/"]
I don’t really have the knowledge outside of developing on individual plugins how to debug further, I wonder if kong.handle_errors() short circuits method calls/blocks that come after it, nor do I know where to look to review the source code of kong.handle_errors() and how content_by_lua_block/log_by_lua_block works with these methods(are they sort of like lua “phases” for when executions should happen?
I may have spoken too fast: I tested on my side that the NGINX log phase was executed, but the kong.log() call will not execute plugins indeed, for another reason: NGINX’s error_page does an internal redirect, which causes ngx.ctx (the value storing the API and plugins to execute for this request) to be reset. Thus, no plugins will be run (Kong even lost the information relating to which API was matched in that particular request at this point).
There seems to be no easy fix for this, we’ll have to add this to our backlog and think of a workaround. Sorry for the false hope!
Thanks for your continued effort looking into this, we too are going to try to find a hack/workaround to make Kong log these scenarios via plugin so we have a full view into api transaction errors from external logging applications. If anyone at Kong starts to think up an idea let us know and we will test it!
Setup easier tracking of this problem on git - https://github.com/Kong/kong/issues/3193
-Jeremy
Any updates on this front? Would it be feasible to copy the entire ngx.ctx to a global var of sorts prior to the error_page internal redirect and still execute kong.log() against that post redirect? Hoping Kong can reach full potential here on transaction logging.
No updates on that front yet. Any experimentation from readers of this topic would be welcome.
What do you think about this possibly yo : https://github.com/openresty/lua-nginx-module/issues/1057 , you think this to be a valid way to do it in Kong and if we did where should this live? Could this be done in the template? Seems agentzh has known about this for awhile:
“The problem is that the nginx core clears all modules’ ctx data upon internal redirects.”
EDIT - Ohhh 3scale api gateway who uses nginx similarly to Kong also wrote a module for it(you can see it tied to the issue I linked above). Initial thought is this would integrate into Kong core rather than a plugin/template(it is Apache 2.0 Licensed) -
https://github.com/3scale/apicast/blob/master/gateway/src/resty/ctx.lua
And Testcase
https://github.com/3scale/apicast/blob/master/t/resty-ctx.t
-Jeremy
Just going to update this post so we can consider the initial problem brought up as closed:
Awesome to see @thibaultcha cook something up that will give Kong much better visibility into API transaction error logging!
Will be interesting to see if there are any performance hits here but I am going to be hopeful it does not cost much! I would pay a few milliseconds regardless to ensure better logging.
@jeremyjpj0916 We came up with two solutions:
Make reference of ctx available for error_page:
https://github.com/Kong/kong/tree/wip/feat/log-plugins-on-error-page
Remove error_page:
https://github.com/Kong/kong/tree/refactor/proxy-error-handling
Both are quite small changes to hot code paths. And there is a third option that is a little bit of both. All solutions have good and bad sides, we need to weight them a bit.
By removing error_page, that rids yourself of the internal redirect in the first place right? But error_page is also how you explicitly state error code to direct to the kong_error_handler
error_page 400 404 408 411 412 413 414 417 494 /kong_error_handler;
error_page 500 502 503 504 /kong_error_handler;
So I guess there was an alternative place that could be made for handling these statuses. Interesting stuff!