Capture nginx webserver error messages in context of kong api tx

[jeremyjpj0916]

My understanding is there is no way today to capture the "timed out reading response header from upstream" that nginx webservers throw out to error log/standard out via the ngx.* variable or the kong.* vars.

I would like to always correlate nginx webserver upstream connection and read write timeout errors especially so if its not a native part of nginx lua or Kong would like a way to grab:

ngx.webserver_errors[0] ... ngx.webserver_errors[n]

Or via kong var:
kong.webserver_errors[0] ... kong.webserver_errors[n]

Typically there is only 1 nginx webserver error message on a tx I think from reverse proxy perspective so might not need a list.

There are ways to kinda do it today I do like so:
https://github.com/Optum/kong-error-log/blob/master/src/handler.lua but this is hacky and at high tx vols confuses different errors with other txs.

[chobits]

My understanding is there is no way today to capture the "timed out reading response header from upstream" that nginx webservers throw out to error log/standard out via the ngx.* variable or the kong.* vars.

Yes, because these error message is hard coded into nginx internal structure, and later nginx just directly output them into error.log.

/path/to/nginx/source $ grep 'reading response header' -R src/
src//http/ngx_http_upstream.c:    c->log->action = "reading response header from upstream";

Note that action string will be auto appended to error message like 
  src/http/ngx_http_upstream.c:        ngx_connection_error(c, NGX_ETIMEDOUT, "upstream timed out");

I would like to always correlate nginx webserver upstream connection and read write timeout errors especially so if its not a native part of nginx lua or Kong would like a way to grab:

ngx.webserver_errors[0] ... ngx.webserver_errors[n]

Or via kong var: kong.webserver_errors[0] ... kong.webserver_errors[n]

I think if we dont modify nginx/openresty source code , it's hard to implement it gracefully.

Typically there is only 1 nginx webserver error message on a tx I think from reverse proxy perspective so might not need a list.

There are ways to kinda do it today I do like so: https://github.com/Optum/kong-error-log/blob/master/src/handler.lua but this is hacky and at high tx vols confuses different errors with other txs.

From the source code, I think it's tricky way to implement the error code detection via raw error.log message and status_code.

[chobits]

According to my experience, in tengine project, we originally introduced a error_flag to nginx's http request/connection structure to record different kinds of error when processing the request, and then we exposed it as a nginx var. But this error_flag feature is not opensourced, just used internally

[jeremyjpj0916]

Yeah fully agree it would take Kong patching nginx/openresty layer to expose it as a fresh ngx variable(kong already do this pretty often anyways w patches to enhance and improve things) but it does help give the ability to give extra insights in your kong api tx logs. I always like knowing if a upstream connection was timed out during the tcp/tls handshake or if it timed out on the read/write for example when backend latency > 0. If we expose that error log as a var field and can ref it in the lua code it becomes dead simple.

My solution works okay to some degree, but at high tx volumes it attaches the wrong message to the wrong tx sometimes in my http logging plugins, plus all that string parsing of it and matchings and looping through the buffer of messages is expensive.

[jeremyjpj0916]

Hoping maybe this can get a jira board ticket for just exposing it as a variable in the tx context possibly and think more on how kong wants to use it. I know how I would use it anyways xD.

[chobits]

I can create an internal ticket, but I can't guarantee the completion time. Generally, changing the Nginx/OpenResty binary requires a lengthy review process. For stability reasons, such requests might not be approved for a long time, if at all.

[chobits]

https://konghq.atlassian.net/browse/KAG-5190.

Its description is like:

Expose a nginx variable for detailed internal error reasons

This requirement means that some users want to know the detailed reason of nginx internal error like 5xx, 
connection error between nginx and client, connection error between ngixn and upstream, connection timeout 
error or connection read/write error, or any other errors that can be reflected in the response.

Some thoughts to implement it, we could introduce a flag into nginx 's request/connection structure, 
then log some error bit to this flag, then expose this flag as a nginx variable to users.

Errors maybe like:
1. connection error - timeout - waiting client
2. connection error - read - from client
3. connection error - write - to client
4. connection error - timeout - waiting upstream
5. connection error - read - from upstream
6. connection error - write - to upstream
7. connection error - connect - to upstream
8. HTTP/2 error: stream limit exceeded, protocol violation
9. ...

The HTTP packet protocol error - from upstream

[jeremyjpj0916]

Yeah I would start simple and if people like the feat then expand it further. But baseline would be knowing when:

1. Client premature closed the connection(that actually assigns a unique http status code so its low priority imo).

2. Upstream connection timeouts.

3. Upstream read/write timeouts.

Where two and 3 are the critical gaps because the only way you can tell if those occur in regular kong tx logs without assessing the webserver logs is by monitoring the upstream latency metrics to see if it was close to the connection timeout ammt or r/w ammt settings. If both were set to the same number, say 2 seconds then it would not even be possible to derive if it was connection or read/wite.