Closed jeremyjpj0916 closed 4 months ago
Thanks for your report, we also already noticed it and are investigating.
We can easily reproduce it by common case
1. Start Kong
2. Send HTTP traffic to the HTTPS port
╰─$ curl 127.0.0.1:8443
<html>
<head><title>400 The plain HTTP request was sent to HTTPS port</title></head>
<body>
<center><h1>400 Bad Request</h1></center>
<center>The plain HTTP request was sent to HTTPS port</center>
</body>
</html>
3. Check the error log
2024/06/13 14:38:43 [warn] 1915011#0: *10309 using uninitialized "kong_proxy_mode" variable while logging request, client: 127.0.0.1, server: kong, request: "GET / HTTP/1.1", host: "127.0.0.1:8443"
2024/06/13 14:38:43 [warn] 1915011#0: *10309 [lua] reports.lua:106: log(): [reports] could not determine log suffix (scheme=http, proxy_mode=) while logging request, client: 127.0.0.1, server: kong, request: "GET / HTTP/1.1", host: "127.0.0.1:8443"
HTTP request was sent to the HTTPS port, and 400 was triggered in the TLS handshake process, it does not initialize any nginx variable, and we can not get the kong_proxy_mode
variable. So this case did not affect any production correctly traffic, just some abnormal traffic.
@oowl I think my case is similar to the http call to an https endpoint but mine was essentially a loadbalancer calling its health check endpoint to a port expecting client mtls that could not serve a client certificate so nginx rejects the call early for no client cert passed. similar early nginx termination of the tx for not meeting tls needs similar to your http protocol mismatch.
< HTTP/2 400
< date: Thu, 13 Jun 2024 15:30:56 GMT
< content-type: text/html; charset=UTF-8
< content-length: 202
< x-response-latency: 0
<
<html>
<head><title>400 No required SSL certificate was sent</title></head>
<body>
<center><h1>400 Bad Request</h1></center>
<center>No required SSL certificate was sent</center>
</body>
</html>
Will this be backported to 3.7.0 or end up in a 3.7.1? For now I will drop in some patch files with your suggested fixes and try it out. In looking at the fix I notice you opted to just move the uninitialized_variable_warn off;
up to the main block so all server blocks can get that benefit. I guess the only concern with that approach may be what if there were totally valid situations where a problematic uninitialized variable was occurring in Kong/Nginx and now that setting will make it so folks don't realize it vs in this situation where its more of a false positive because the tx .
@chronolaw I also saw a different error too w respect to my original post, the
2024-06-12T20:34:00.799776653-05:00 2024/06/13 01:34:00 [notice] 133442#0: *169848 [kong] globalpatches.lua:147 [kong-kafka-log] request headers truncated while logging request, client: xxx.xxx.x.xxx, server: kong_mtls, request: "GET /F5/status HTTP/1.1", host: "gateway-dev-dc.company.com"
It likely may be related similarly due to short circuited txs though but it prints w the globalpatches lua file line.
So @chronolaw @oowl I dropped in the nginx template change to move the no warning on the uninit vars + patched the reports.lua file and that did fix one of the log issues I saw.
Still getting this log though on both my server blocks:
2024-06-13T12:50:49.035418672-05:00 2024/06/13 17:50:49 [notice] 50#0: *2958 [kong] globalpatches.lua:147 [kong-kafka-log] request headers truncated while logging request, client: xxx.xxx.x.xxx, server: kong, request: "GET /F5/status HTTP/1.1", host: "gateway-dev-dc.company.com", request_id: "d3ecff4fcd1cdf42a7f7aa2fd2b39847"
2024-06-13T12:50:49.041943127-05:00 2024/06/13 17:50:49 [notice] 48#0: *2956 [kong] globalpatches.lua:147 [kong-kafka-log] request headers truncated while logging request, client: xxx.xxx.x.xxx, server: kong_mtls, request: "GET /F5/status HTTP/1.1", host: "gateway-dev-dc.company.com"
Studying this code here from global patches:
local DEFAULT_MAX_REQ_HEADERS = 100
local DEFAULT_MAX_RESP_HEADERS = 100
local DEFAULT_MAX_URI_ARGS = 100
local DEFAULT_MAX_POST_ARGS = 100
local DEFAULT_MAX_DECODE_ARGS = 100
local MAX_REQ_HEADERS
local MAX_RESP_HEADERS
local MAX_URI_ARGS
local MAX_POST_ARGS
local MAX_DECODE_ARGS
-- REQUEST HEADERS [
local function get_req_headers_real(max_req_headers, ...)
local request_headers, err = get_req_headers(max_req_headers or MAX_REQ_HEADERS or DEFAULT_MAX_REQ_HEADERS, ...)
if err == "truncated" then
kong.log.notice("request headers truncated")
end
return request_headers, err
end
_G.ngx.req.get_headers = function(max_req_headers, ...)
if not get_request() then
error("no request found")
end
MAX_REQ_HEADERS = kong and kong.configuration and kong.configuration.lua_max_req_headers or DEFAULT_MAX_REQ_HEADERS
_G.ngx.req.get_headers = get_req_headers_real
return get_req_headers_real(max_req_headers or MAX_REQ_HEADERS, ...)
end
-- ]
Seems basically Kong OOTB now limits req/resp headers to 100 elements each? Thats about on par with most load balancer defaults too from what I have seen from a safety standpoint. BUT the kicker here is I am fairly confident that there were less than 100 request headers to that ping endpoint healthcheck call.... so something about transactions cut short by nginx causing this behavior too in logging plugins? Does this global patches just execute with every plugin? Its odd to me that the http-log plugin isn't printing this also on those txs only my kong-kafka-log plugin.
https://github.com/Optum/kong-kafka-log
Another one of those behaviors I haven't observed on 2.8.x
More proof of it, even curling our health check endpoint on it that has the request termination plugin on it on a custom path from the initial route path defined adding /test showed the behavior on a dummy OOTB curl call:
Am starting to think its any route that has the request termination enabled on it. Testing to confirm that behavior further rn. Adding req termination to another unique route proxy on Kong.
I run all logging plugins globally, the request termination plugin to the healthcheck is local to the route and has this config:
{
"config": {
"echo": false,
"status_code": 200,
"message": "Success",
"body": null,
"content_type": null,
"trigger": null
},
"protocols": [
"grpc",
"grpcs",
"http",
"https"
],
"service": null,
"id": "b0df0260-d82d-4d17-bd85-59f73b50e7a7",
"enabled": true,
"created_at": 1713993860,
"instance_name": null,
"consumer": null,
"route": {
"id": "12b9f530-b292-49d1-8651-ccb7f304c85d"
},
"updated_at": 1717537316,
"name": "request-termination",
"tags": null
}
Darn nope, tried a new route defined without the request termination plugin and it still threw that log, so that plugin has nothing to do with it:
2024-06-13T20:04:19.524000997-05:00 2024/06/14 01:04:19 [notice] 107745#0: *113552 [kong] globalpatches.lua:147 [kong-kafka-log] request headers truncated while logging request, client: 10.xx.xxx.xx, server: kong, request: "GET /F5/status/no-termination HTTP/1.1"
Gonna just disable the kong-kafka-log plugin all together and see if that stops the global patches behavior when it runs too.
Edit - yep with that plugin disabled when I hit the /F5/status proxy healthcheck I don't see the global patches header truncate logging issue. Maybe I can patch global patches lua to give me a print statement of how many headers it thinks it sees and re-enable the kong-kafka-log plugin?
Will this be backported to 3.7.0 or end up in a 3.7.1?
In the current fix, I think we do not backport to the old version.
I guess the only concern with that approach may be what if there were totally valid situations where a problematic uninitialized variable was occurring in Kong/Nginx and now that setting will make it so folks don't realize it vs in this situation where its more of a false positive because the tx .
Yeah, it will let us not realize this error, but from my perspective, it's not a problem in Kong, even if we know this error log, we still do not see what we can do.
@chronolaw @oowl Would you like a separate git issue for the other log issue I mentioned seeing with Kong interacting badly in the core code with one of my OSS plugins when its enabled? I finally added some debug statements to the global patches lua file and confirmed there is some weird behavior up in the 3.7.0 kong verse here hah:
Code change to help debug was this:
-- REQUEST HEADERS [
local function get_req_headers_real(max_req_headers, ...)
local request_headers, err = get_req_headers(max_req_headers or MAX_REQ_HEADERS or DEFAULT_MAX_REQ_HEADERS, ...)
if err == "truncated" then
-- How many headers did this request actually have?!?!?!
local req_header_count = 0
for _ in pairs(get_req_headers(0)) do req_header_count = req_header_count + 1 end
kong.log.notice("Total count of request headers per nginx: " .. tostring(req_header_count))
kong.log.notice("Size of max_req_headers: " .. tostring(max_req_headers))
kong.log.notice("Size of MAX_REQ_HEADERS: " .. tostring(MAX_REQ_HEADERS))
kong.log.notice("Size of DEFAULT_MAX_REQ_HEADERS: " .. tostring(DEFAULT_MAX_REQ_HEADERS))
kong.log.notice("request headers truncated")
end
return request_headers, err
end
Output of the above to help debug was this:
2024-06-18T03:22:44.560652686-05:00 2024/06/18 08:22:44 [notice] 48#0: *3181 [kong] globalpatches.lua:152 [kong-kafka-log] Total count of request headers per nginx: 4 while logging request, client: xxx.xxx.96.250, server: kong, request: "GET /F5/status HTTP/1.1", host: "my-gateway.company.com", request_id: "45b78b56afac4336d75f0d66a5374654"
2024-06-18T03:22:44.560681918-05:00 2024/06/18 08:22:44 [notice] 48#0: *3181 [kong] globalpatches.lua:153 [kong-kafka-log] Size of max_req_headers: 1 while logging request, client: xxx.xxx.96.250, server: kong, request: "GET /F5/status HTTP/1.1", host: "my-gateway.company.com", request_id: "45b78b56afac4336d75f0d66a5374654"
2024-06-18T03:22:44.560685734-05:00 2024/06/18 08:22:44 [notice] 48#0: *3181 [kong] globalpatches.lua:154 [kong-kafka-log] Size of MAX_REQ_HEADERS: 100 while logging request, client: xxx.xxx.96.250, server: kong, request: "GET /F5/status HTTP/1.1", host: "my-gateway.company.com", request_id: "45b78b56afac4336d75f0d66a5374654"
2024-06-18T03:22:44.560688618-05:00 2024/06/18 08:22:44 [notice] 48#0: *3181 [kong] globalpatches.lua:155 [kong-kafka-log] Size of DEFAULT_MAX_REQ_HEADERS: 100 while logging request, client: xxx.xxx.96.250, server: kong, request: "GET /F5/status HTTP/1.1", host: "my-gateway.company.com", request_id: "45b78b56afac4336d75f0d66a5374654"
2024-06-18T03:22:44.560698082-05:00 2024/06/18 08:22:44 [notice] 48#0: *3181 [kong] globalpatches.lua:156 [kong-kafka-log] request headers truncated while logging request, client: xxx.xxx.96.250, server: kong, request: "GET /F5/status HTTP/1.1", host: "my-gateway.company.com", request_id: "45b78b56afac4336d75f0d66a5374654"
So I think the real issue is why the heck was max_req_headers
set to 1 during the context of this transaction? Only allowed 1 header element by Kong lol? All the other variables were at 100 which is reasonable but the value of 1 makes no sense in this situation. Why are there so many OR statements in there all setting the size vs 1 simple variable value that could also maybe be configured/overriden as an environment variable for max header count # ? I am not setting anything in my env variables around anything like that either. Seems way over complicated in that code block.
Edit - Ohhhh is it because of this? https://github.com/Optum/kong-kafka-log/blob/master/src/basic.lua#L146 ???? This logic used to work fine using ngx.req.get_headers(1)["optum-cid-ext"] before on 2.8.x ... Does the global patches now override that default nginx header grabbing behavior to cause that issue? Did Kong ever note this in its change log somewhere? I think thats the issue that Kong now overrides that ngx method globally which changed the methods behavior :/ ...
Edit Edit - Per docs it seems like to grab 1 header no arg is even needed inside at all now, maybe it even changed at openresty layer I guess because I don't want that to log "truncating headers" every time. I can update plugin:
Mystery solved.
^ will say I don't agree w notice log for the truncate headers kong does w global patches there either when I just wanna grab a singular header value for optimization. but I removed the (1) and that made the log go away even though I suppose the query is more intensive after doing so.
Is there an existing issue for this?
Kong version (
$ kong version
)3.7.0
Current Behavior
Logs like this are popping up in 1 of my 2 dev environments:
Expected Behavior
No logs like this ideally.
I see upstream_uri present all around in the template and in my kong_mtls block that is basically a dup of the typical kong server block other than the fact is also requires mtls client comms ingress. My first thought was maybe when yall implemented this bit
It only works for the kong server block and not for custom templates that maybe duplicate it twice essentially? But its in the http block so I imagined it would apply anything kong specific to both server blocks... and my kong_mtls block is identical to my kong server block with respect to where upstream_uri shows as present so I am not sure why it throws that.
The other line seems to invoke on the global patches lua file of kong here and I never recall that line comming up on Kong 2.8.x with respect to running this plugin: https://github.com/Kong/kong/blob/3.7.0/kong/globalpatches.lua#L147
Is it like when a plugin sees a header too big or too many headers it throws that log statement? Is there some new limiter to header sizes being applied perhaps snagging me here? Relevant plugin https://github.com/Optum/kong-kafka-log
Worth noting the
/F5/status
calls are just GET requests with no bodies essentially very plain health check calls. That endpoint runs the request termination plugin on the route resource.Steps To Reproduce
Hard to say, including my nginx custom template here for speculation:
Anything else?
No response