URI is sometimes `/kong_error_handler` on upstream status 502s

[fv316]

Is there an existing issue for this?

• [X] I have searched the existing issues

Kong version ($ kong version)

kong:3.4.2-ubuntu

Current Behavior

In our logs some requests for which the upstream status is 502 have their $uri variable overridden so that when Kong logs this request the log line appears to have /kong_error_handler as the URI. This is seen in the log line below (I have removed some of the log fields).

2024-01-01 00:00:00.000	
{
  "uri": "/kong_error_handler",
  "status": "502",
  "upstream_status": "502",
  "upstream_response_time": "0.001",
  "upstream_response_length": "0",
}

Which corresponds to this log format

nginx_http_log_format: "main escape=json '{ \"uri\": \"$uri\", \"status\": \"$status\", \"upstream_status\": \"$upstream_status\", \"upstream_response_time\": \"$upstream_response_time\", \"upstream_response_length\": \"$upstream_response_length\"}'"

This is also reflected on the Prometheus metrics since these 502s which appear to originate from the upstream but have the $uri parameter overridden appear on the kong_http_requests_total metric as having the source as kong rather than the service.

It seems that the upstream does NOT return 502 for these requests (the request never reaches the upstream).

Expected Behavior

The URI should match the $uri field should match the request URI (something like api/v1/things). The $upstream_status should not be 502.

Steps To Reproduce

This error happens intermittently and I cannot reproduce it.

Anything else?

We are trying to create alerts based on errors that originate from Kong. However, this bug prevents us from using the kong_http_requests_total metric to create alerts.

[jschmid1]

Thanks for reporting @fv316. This indeed sounds like unintended behavior. We'll discuss this internally and come back to you.

[chronolaw]

@jschmid1 , do we have any update?

[ADD-SP]

Internal ticket for tracking this issue: KAG-4587

[davidmontoyago]

Hi everyone, we're also observing this issue on KIC 2.10.5 and proxy 2.8.4.4. It happens for 502s as well as 504s.

[vpilania]

I observe this for kong 2.6.0 for all 4xx & 5xx errors. How to have that print out the actual api or uri_path being called instead? You can see most of the critical details are either empty or of no use. Any help on how I can see the expected behaviour is highly appreciated!

Sample logs:

23/Jul/2024:00:21:34 +0000 site="kong" server="kong" dest_port="443" dest_ip="10.xxx.xxx.xxx" src="10.xxx.xxx.xxx" src_ip="10.xxx.xxx.xxx" user="-" protocol="-" status="400" bytes_out="12" bytes_in="-" http_referer="-" http_user_agent="-" nginx_version="1.19.9" http_x_forwarded_for="-" http_x_header="-" uri_query="-" uri_path="/kong_error_handler" http_method="GET" response_time="-" cookie="-" request_time="0.002" uct="-" uht="-" kong_proxy_latency="-" kong_upstream_latency="-" Trace_ID="-" Proxy-Request-ID="-" x-consumer-username="-" flavor="ec2" aws_region="us-west-2" role-name="flight"