feat(core) add `X-Kong-Upstream-Status` header #3263

hbagdi · 2018-02-26T22:37:31Z

While Kong returns the same status code as
that of the upstream when it proxies a request,
it is useful to record the real status code
returned by the upstream.

This can be used for monitoring Kong
itself if it is returning the same response
as the upstream.

Summary

Add an upstream status header to proxied requests

hbagdi · 2018-02-26T22:37:42Z

cc @maguec

maguec · 2018-02-26T22:40:34Z

+1
This will be needed for cloud as well as is very useful for troubleshooting on-site

guanlan · 2018-02-26T22:43:23Z

kong/constants.lua

@@ -41,6 +41,7 @@ return {
    HOST_OVERRIDE = "X-Host-Override",
    PROXY_LATENCY = "X-Kong-Proxy-Latency",
    UPSTREAM_LATENCY = "X-Kong-Upstream-Latency",
+	UPSTREAM_STATUS = "X-Kong-Upstream-Status",


Can you fix the indent?

guanlan · 2018-02-26T22:53:13Z

kong/core/handler.lua

@@ -523,6 +523,7 @@ return {
        local now = get_now()
        ctx.KONG_WAITING_TIME = now - ctx.KONG_ACCESS_ENDED_AT -- time spent waiting for a response from upstream
        ctx.KONG_HEADER_FILTER_STARTED_AT = now
+		header[constants.HEADERS.UPSTREAM_STATUS]  = ngx.status


@hbagdi @thibaultcha I might be wrong here, I remember ngx.status indicates the current request's response status, the accurate upstream status should come from a nginx variable: "ngx.var.upstream_status", see http://nginx.org/en/docs/http/ngx_http_upstream_module.html#var_upstream_status

This header should be nested under the feature flag test for server_tokens (see below). Ideally, another flag for "debugging tokens" could be added at some point, but "server_tokens" is the one we use today in accordance with NGINX.

thibaultcha

Will you provide a test case better describing the scenario you are trying to over with this? I know you will, just making sure :)

Thanks

thibaultcha · 2018-02-26T23:03:37Z

kong/core/handler.lua

@@ -523,6 +523,7 @@ return {
        local now = get_now()
        ctx.KONG_WAITING_TIME = now - ctx.KONG_ACCESS_ENDED_AT -- time spent waiting for a response from upstream
        ctx.KONG_HEADER_FILTER_STARTED_AT = now
+		header[constants.HEADERS.UPSTREAM_STATUS]  = ngx.status


This header should be nested under the feature flag test for server_tokens (see below). Ideally, another flag for "debugging tokens" could be added at some point, but "server_tokens" is the one we use today in accordance with NGINX.

thibaultcha · 2018-02-26T23:04:43Z

FYI, you can create custom plugins for the tests in the spec/fixtures folder - and update/write a plugin to highlight the use-case for this header.

guanlan · 2018-02-27T18:55:56Z

LGTM

hbagdi · 2018-02-27T18:59:36Z

@guanlan This is work in progress, need to add a test case when there is a responses mismatch between Kong's response and upstream's response.
Will notify once everything is ready and passes tests cases.

not read (besides we are in feature freeze)

hbagdi · 2018-02-28T02:19:54Z

@guanlan @thibaultcha Please take another look over this. Thank you.

hbagdi · 2018-03-13T03:38:02Z

@thibaultcha ping

thibaultcha · 2018-03-13T04:00:40Z

kong/core/handler.lua

      if ctx.KONG_PROXIED then
        local now = get_now()
        ctx.KONG_WAITING_TIME = now - ctx.KONG_ACCESS_ENDED_AT -- time spent waiting for a response from upstream
        ctx.KONG_HEADER_FILTER_STARTED_AT = now
      end
+
+      if singletons.configuration.server_tokens then


This is tricky. Upon re-reading the description for both server_tokens and latency_tokens, this new header does not fall under either category. After giving it some thoughts, I have been thinking of changing how we specify those headers... bear with me.

As we strive towards a simpler configuration file (with less directive, but no less flexibility, and more intuitiveness), we can follow a similar approach as #3147, and provide a new way to configure such headers served by Kong, like so:

tokens = [server|latency|debug|off] custom ...

A few examples of which headers are served with each setting:

tokens = server Via: ... (or Server: ... upon non-proxying) - same behavior as server_tokens = on tokens = latency X-Kong-Proxy-Latency: ... X-Kong-Upstream-Latency: ... (same behavior as latency_tokens = on token = server, latency same as both previous examples tokens = debug All previous headers plus: X-Kong-Upstream-Status X-Kong-Matched-API (already present in the router when the Kong-Debug request header is set) tokens = X-Kong-Upstream-Latency Only send the upstream latency header tokens = off No header will be injected by Kong core

I know this is more work than this PR originally intended to be, but I hope you can see where I am coming from here. We want to provide a configuration file that makes sense and is intuitive.

thibaultcha · 2018-03-20T03:13:51Z

Moved to #3300 from what I can tell? If so, will you please close this and delete the branch? Thanks!

hbagdi · 2018-03-20T03:18:44Z

@thibaultcha I was planning to put in X-Kong-Proxy-Status as a separate commit and #3300 is just changing the configuration. I'll rebase this and update once #3300 goes through.

hbagdi · 2018-04-21T18:24:51Z

@thibaultcha I've reworked this PR to use the work we did in #3300.

thibaultcha · 2018-04-25T22:46:07Z

kong/core/handler.lua

+
+      if singletons.configuration.headers[constants.HEADERS.UPSTREAM_STATUS] then
+        header[constants.HEADERS.UPSTREAM_STATUS]  = var.upstream_status
+      end


$upstream_status can contain a comma-separated list of upstream status codes if several upstreams were selected. I see no test case covering this, so I am wondering if it is an oversight?

Regardless, my understanding of this header is that it would return the status code of the last upstream request (others are tracked by the healthchecks and transparent to the client). Thoughts?

style: note the 2 spaces before = as well.

In any case, this is an oversight.

I agree that this header should return the last upstream status and multiple upstream retries for the same request should happen transparently.

I'm assuming that you agree with the above implementation and will work on it and ping you back.

thibaultcha · 2018-04-30T21:43:56Z

kong/runloop/handler.lua

+
+      local upstream_header = constants.HEADERS.UPSTREAM_STATUS
+      if singletons.configuration.headers[upstream_header] then
+        header[upstream_header] = string.match(var.upstream_status, "(%S+)$")


Unfortunately, string.match is part of the NYI (Not Yet Implemented) LuaJIT API (meaning it will not JIT compile, and thus prevent the creation of a trace in this chunk), which is a problem for such hot code paths. Introducing non-JITable code paths in the proxy path has given us performance regressions in the past, and we should be mindful about them.

Instead, you may use the PCRE API offered by ngx.re, or any other trick you may think of to extract this value in plain Lua (the former is probably healthier).

If anyone is interested in viewing the entire list of NYI methods. As I was curious myself.

As it is in our CONTRUBITING.md file, we expect all contributors to have read this list already :)

I was trying to be a little less forward about where I found it 😏

Thanks for pointing this out. I never gave NYI LuaJIT methods much thought before. Will be more careful next time.

@hbagdi also keep in mind that without the "jo" flag, ngx.re.match can be (much!) slower than string.match.

@hishamhm Thank you for pointing this out!

thibaultcha · 2018-04-30T21:47:24Z

spec/02-integration/05-proxy/14-upstream-status-header_spec.lua

+    local route1 = bp.routes:insert {
+      protocols = { "http" },
+      service = service,
+      paths = { "/foo" },


(Minor) one piece of advice here: these tests tend to grow quite fast and using paths such as /foo etc quickly makes them unmanageable (several hundreds of lines down in the same files, you might not remember what the /foo path maps to).

I would advise the use of /status/200 or /status/500 (or any other more explicit name you may think of) instead. Not really a blocker, but if you care enough to change them, it'd be appreciated.

I see your point and have personally experienced this problem in a couple of test files myself. I'll update this to use more descriptive names.

thibaultcha · 2018-04-30T21:48:43Z

spec/02-integration/05-proxy/14-upstream-status-header_spec.lua

+        }
+      })
+      assert.res_status(200, res)
+      assert.equal('200', res.headers[constants.HEADERS.UPSTREAM_STATUS])


style: let's avoid single quotes altogether when possible - if we ever enforce this in our linter we'd have to fix a ton of places.

thibaultcha · 2018-04-30T21:49:34Z

spec/02-integration/05-proxy/14-upstream-status-header_spec.lua

+      if client then
+        client:close()
+      end
+      helpers.stop_kong(nil, nil, true)


Using true in arguments to helpers.stop_kong should be for debugging purposes only. This is a leftover probably? There are other places in this file.

This was used to avoid truncating tables between tests runs in this file since stop_kong will truncate them by default. Should it still be avoided?

thibaultcha · 2018-04-30T21:51:27Z

spec/02-integration/05-proxy/14-upstream-status-header_spec.lua

+      service = service,
+      paths = { "/bar" },
+    }
+    assert(route2)


The Lua idiom we follow is to wrap the :insert() call within an assert(). The new DAO is built for this purpose in mind, since the second return value will be a string, thus producing the equivalent of assert(nil, err_from_insert). This is a typical use of assert and errors with Lua. In the current case, the assert would fail but no errors would be printed explaining why. It's also shorter and more eleguant.

Thanks for explaining this, I'll keep in mind next time. Updated this in the most recent push.

thibaultcha · 2018-05-02T03:37:49Z

spec/02-integration/05-proxy/14-upstream-status-header_spec.lua

+local constants = require "kong.constants"
+
+local function setup_db()
+  ngx.log(ngx.ERR, "before aeach  called" )


Let's remove logging from the tests (noisy and we spent time removing a bunch by the past already)

thibaultcha · 2018-05-02T03:38:08Z

spec/02-integration/05-proxy/14-upstream-status-header_spec.lua

+    port = helpers.mock_upstream_port,
+    protocol = helpers.mock_upstream_protocol,
+  }
+  assert(service)


seems like this assert still isn't in the right place?

thibaultcha · 2018-05-02T04:28:35Z

kong/runloop/handler.lua

+        local matches, err = ngx.re.match(var.upstream_status,
+                                          "[0-9]+$", "oj")
+        if err then
+          log(ERR, "failed to set upstream status header", err)


This message is wrongly formatted. It is also somewhat obscure. It should be better formatted and cold be clarified, like so:

log(ERR, "failed to set ", upstream_status_header, " header: ", err)

(Notice the more appropriate name for the upstream_header variable as well...)

thibaultcha · 2018-05-02T04:29:47Z

kong/runloop/handler.lua

+
+      local upstream_header = constants.HEADERS.UPSTREAM_STATUS
+      if singletons.configuration.headers[upstream_header] then
+        local matches, err = ngx.re.match(var.upstream_status,


This should be cached at the top level chunk of this file according to style and this file's conventions:

re_match = ngx.re.match

X-Kong-Upstream-Status header returns the status code returned by the upstream API. This header is disabled by default and can be enabled by adding it to `headers` config property in kong.conf.

thibaultcha · 2018-05-02T23:37:37Z

spec/02-integration/05-proxy/14-upstream-status-header_spec.lua

+
+local function setup_db()
+  local bp = helpers.get_db_utils()
+  assert(helpers.dao:run_migrations())


FYI, the get_db_utils() utility will run the migrations for you :) I am proceeding with the merge at this point and will fix it locally, but for next time!

thibaultcha · 2018-05-03T00:06:36Z

kong/runloop/handler.lua

+
+      local upstream_status_header = constants.HEADERS.UPSTREAM_STATUS
+      if singletons.configuration.headers[upstream_status_header] then
+        local matches, err = re_match(var.upstream_status,


It just struck me that we are missing a case here that would result in a guaranteed timeout when the request was short-circuited by a plugin (e.g. authentication) because the variable would be an empty string, and there would be no match, and we'd be indexing a nil value below. We should either nest this below the above if proxied branch, or program defensively against such a case. I will be adding a regression test and making that change in the merge.

A tweaked version of this came to my mind if the code would insert this header for not proxied requests as well but seems like my understanding was wrong. Proxied request means that a request actually hits the upstream. Thank you for catching this!

If enabled, the `X-Kong-Upstream-Status` header is injected by Kong in the response for the client. It contains the status code returned by the upstream response. This header is disabled by default, and can be enabled by adding it to the `headers` configuration property. From #3263 Signed-off-by: Thibault Charbonnier <thibaultcha@me.com>

thibaultcha · 2018-05-03T00:25:21Z

Manually merged with the discussed tweaks. Thanks!

…atus header The hotfix commit 75e071b (#3419) changes the configuration property from `headers` to `enabled_headers`. The commit did not update a conditional statement introduced in 60c335e (#3263). This commit corrects the check from `headers` to `enabled_headers`. This was caught by the test suite and hence no regression test has been added.

The hotfix commit 75e071b (#3419) changes the configuration property from `headers` to `enabled_headers`. The commit did not update a conditional statement introduced in 60c335e (#3263). This commit corrects the check from `headers` to `enabled_headers`. This was caught by the test suite and hence no regression test has been added. From #3433

guanlan reviewed Feb 26, 2018

View reviewed changes

thibaultcha requested changes Feb 26, 2018

View reviewed changes

hbagdi force-pushed the feat/upstream-status-header branch from f36e5c8 to e73e9b6 Compare February 27, 2018 18:24

guanlan previously approved these changes Feb 27, 2018

View reviewed changes

hbagdi force-pushed the feat/upstream-status-header branch 3 times, most recently from 8d9caf7 to 8cb77bd Compare February 28, 2018 01:20

thibaultcha reviewed Mar 13, 2018

View reviewed changes

thibaultcha added pr/status/do not merge (to discuss) pr/changes requested Changes were requested to this PR by a maintainer. Please address them and ping back once done. and removed pr/do not merge labels Mar 13, 2018

hbagdi force-pushed the feat/upstream-status-header branch from 8cb77bd to 3a8e601 Compare April 20, 2018 22:56

hbagdi changed the base branch from master to next April 21, 2018 15:04

hbagdi force-pushed the feat/upstream-status-header branch from 3a8e601 to ac628c7 Compare April 21, 2018 15:18

hbagdi added pr/please review and removed pr/changes requested Changes were requested to this PR by a maintainer. Please address them and ping back once done. labels Apr 21, 2018

thibaultcha reviewed Apr 25, 2018

View reviewed changes

hbagdi force-pushed the feat/upstream-status-header branch 2 times, most recently from 73e5394 to eb15304 Compare April 27, 2018 18:54

hbagdi force-pushed the feat/upstream-status-header branch from eb15304 to 41df399 Compare April 28, 2018 03:05

thibaultcha requested changes Apr 30, 2018

View reviewed changes

hbagdi force-pushed the feat/upstream-status-header branch 2 times, most recently from 17690b2 to 736a801 Compare May 1, 2018 00:34

thibaultcha reviewed May 2, 2018

View reviewed changes

feat(core) add ability to inject X-Kong-Upstream-Status header

141c076

X-Kong-Upstream-Status header returns the status code returned by the upstream API. This header is disabled by default and can be enabled by adding it to `headers` config property in kong.conf.

hbagdi force-pushed the feat/upstream-status-header branch from 3966db9 to 141c076 Compare May 2, 2018 15:18

[squash] lint

2d80203

thibaultcha reviewed May 2, 2018

View reviewed changes

thibaultcha reviewed May 3, 2018

View reviewed changes

thibaultcha closed this May 3, 2018

thibaultcha deleted the feat/upstream-status-header branch May 3, 2018 00:25

hbagdi mentioned this pull request May 3, 2018

hotfix(core) check enabled_headers while injecting X-Kong-Upstream-Status header #3433

Merged

feat(core) add X-Kong-Upstream-Status header #3263

feat(core) add X-Kong-Upstream-Status header #3263

Conversation

hbagdi commented Feb 26, 2018 • edited Loading

Summary

hbagdi commented Feb 26, 2018

maguec commented Feb 26, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

thibaultcha left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

thibaultcha commented Feb 26, 2018

guanlan commented Feb 27, 2018

hbagdi commented Feb 27, 2018

hbagdi commented Feb 28, 2018

hbagdi commented Mar 13, 2018

Choose a reason for hiding this comment

thibaultcha commented Mar 20, 2018

hbagdi commented Mar 20, 2018 • edited Loading

hbagdi commented Apr 21, 2018

thibaultcha Apr 25, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

thibaultcha Apr 30, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

thibaultcha May 3, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

thibaultcha commented May 3, 2018

feat(core) add `X-Kong-Upstream-Status` header #3263

feat(core) add `X-Kong-Upstream-Status` header #3263

hbagdi commented Feb 26, 2018 •

edited

Loading

hbagdi commented Mar 20, 2018 •

edited

Loading

thibaultcha Apr 25, 2018 •

edited

Loading

thibaultcha Apr 30, 2018 •

edited

Loading

thibaultcha May 3, 2018 •

edited

Loading