queue-proxy：Invalid request log template

[liuyuxuan0723]

What version of Knative?

1.11.2

Expected Behavior

Configured the request logging template following https://knative.dev/docs/serving/observability/logging/request-logging/

logging.request-log-template: >-
    {"requestMethod": "{{.Request.Method}}", "requestUrl": "{{js
    .Request.RequestURI}}", "requestSize": {{.Request.ContentLength}}, "code":
    {{.Response.Code}}, "responseSize": {{.Response.Size}}, "userAgent": "{{js
    .Request.UserAgent}}", "remoteIp": "{{js .Request.RemoteAddr}}", "serverIp":
    "{{.Revision.PodIP}}", "referer": "{{js .Request.Referer}}", "latency":
    {{.Response.Latency}}, "protocol": "{{.Request.Proto}}", "traceID": "{{index
    (index .Request.Header "X-B3-Traceid") 0}}","msg":"Finished handling
    request."}

Expected to output trace ID in the request logs:

{"requestMethod": "POST", "requestUrl": "/", "requestSize": 559, "code": 200, "responseSize": 27, "userAgent": "go-resty/2.16.5 (https://github.com/go-resty/resty)", "remoteIp": "10.36.180.90:53598", "serverIp": "10.36.134.94", "referer": "", "latency": 6.950939235, "protocol": "HTTP/1.1", "traceID": "012bf535a144fa584d40fe791b04ce18","msg":"Finished handling request."}

Actual Behavior

During traffic spikes, some request logs fail to parse according to the template and show the following error. I confirmed that every request comes from the same client and includes the X-B3-Traceid header.

{"requestMethod": "POST", "requestUrl": "/", "requestSize": 560, "code": 200, "responseSize": 27, "userAgent": "go-resty/2.16.5 (https://github.com/go-resty/resty)", "remoteIp": "10.36.183.136:42866", "serverIp": "10.36.178.75", "referer": "", "latency": 0.070215634, "protocol": "HTTP/1.1", "traceID": "Invalid request log template: method: POST, response code: 200, latency: 0.098454743, url: /

Steps to Reproduce the Problem

This occurs with some probability every time there's a traffic spike, but the root cause is uncertain.

[dprotaso]

Curious are the pods crashing for any reason?

[liuyuxuan0723]

@dprotaso
I checked the monitoring and K8s events and found no restarts or crashes. Looking at the qp (queue-proxy) logs, it appears to have exited normally.

I have provided the complete qp logs, which show that "Invalid request log template" errors started appearing from 17:34:24, but the graceful shutdown occurred at 17:42:52.

26df2f2b-0b2a-4072-adcd-5bbf134ee6a1.csv.gz

[dprotaso]

We're using standard go templating here - I'm wondering if the error message is accurate and your request template isn't valid.

   {"requestMethod": "{{.Request.Method}}", "requestUrl": "{{js
    .Request.RequestURI}}", "requestSize": {{.Request.ContentLength}}, "code":
    {{.Response.Code}}, "responseSize": {{.Response.Size}}, "userAgent": "{{js
    .Request.UserAgent}}", "remoteIp": "{{js .Request.RemoteAddr}}", "serverIp":
    "{{.Revision.PodIP}}", "referer": "{{js .Request.Referer}}", "latency":
    {{.Response.Latency}}, "protocol": "{{.Request.Proto}}", "traceID": "{{index
    (index .Request.Header "X-B3-Traceid") 0}}","msg":"Finished handling
    request."}

Looking at the code now - we don't log the error when executing.

serving/pkg/http/request_log.go

Line 181 in 940713f

fmt.Fprintf(h.writer, "Invalid request log template: method: %v, response code: %v, latency: %v, url: %v\n",

[dprotaso]

It seems like we should return after writing the invalid request log but it seems like we'll fall through and then write what's in the buffer

serving/pkg/http/request_log.go

Line 184 in 940713f

h.writer.Write(w.Bytes())

[liuyuxuan0723]

Got it. From the logs, it looks like the template should be working, but it's strange that only certain requests are showing the "Invalid request log template" error. I'll try printing out the specific error first to troubleshoot the issue.

[dprotaso]

hey @liuyuxuan0723 just following up if where able to the log the error?

[liuyuxuan0723]

@dprotaso Sorry for the delay, I've been quite busy with work lately. I retested today and printed detailed request log errors, and indeed found that there are no corresponding trace headers:

Invalid request log template: error: template: requestLog:1:431: executing "requestLog" at <index (index .Request.Header "X-B3-Traceid") 0>: error calling index: reflect: slice index out of range, method: GET, response code: 502, latency: 0.008973105, url: /, headers: map[Forwarded:[proto=http] Knative-Serving-Namespace:[faasdev-dev] Knative-Serving-Revision:[lfc-kf2ajw7e-00016] X-Forwarded-Proto:[http] X-Request-Id:[8b7fca80-4e2f-4642-a2c9-9ad0aa1d28a5]]

The modified code part is as follows:

func (h *RequestLogHandler) write(t *template.Template, in *RequestLogTemplateInput) {
	// Use a buffer to store the whole template expansion first. If h.writer is
	// used directly, parallel template executions may result in interleaved output.
	w := bufPool.Get().(*bytes.Buffer)
	w.Reset()
	defer bufPool.Put(w)

	if err := t.Execute(w, in); err != nil {
		// Template execution failed. Write an error message with some basic information about the request.
		fmt.Fprintf(h.writer, "Invalid request log template: error: %v, method: %v, response code: %v, latency: %v, url: %v, headers: %v\n",
			err, in.Request.Method, in.Response.Code, in.Response.Latency, in.Request.URL, in.Request.Header)
		return
	}
	h.writer.Write(w.Bytes())
}

However, I'm still curious why there's no corresponding trace ID. The kourier network layer should inject the corresponding trace information. I tried to directly request kourier's address:

 curl http://172.24.184.109 \
-H "Host: lfc-kf2ajw7e.faasdev-dev.kourier.chj.cloud"
{"message":"hello world"}%

It correctly printed the trace information:

{"requestMethod": "GET", "requestUrl": "/", "requestSize": 0, "code": 200, "responseSize": 25, "userAgent": "curl/8.7.1", "remoteIp": "10.66.144.57:33816", "serverIp": "172.24.165.229", "referer": "", "latency": 0.009288795, "protocol": "HTTP/1.1", "traceID": "ef79ad05d3326f88df79146c80956222","msg":"Finished handling request."}

Load testing kourier:

 wrk -t 100 -c 5000 -d 30s --timeout 10s --latency \                                                                                        base   06:00:55 PM
  -H "Host: lfc-kf2ajw7e.faasdev-dev.kourier.chj.cloud" \
  http://172.24.184.109/

I found that some requests are missing trace information:

Invalid request log template: error: template: requestLog:1:431: executing "requestLog" at <index (index .Request.Header "X-B3-Traceid") 0>: error calling index: reflect: slice index out of range, method: GET, response code: 200, latency: 0.004244741, url: /, headers: map[Forwarded:[proto=http] Knative-Serving-Namespace:[faasdev-dev] Knative-Serving-Revision:[lfc-kf2ajw7e-00016] X-Forwarded-Proto:[http] X-Request-Id:[7f6ce212-490e-4001-a1ec-8146bf2403e3]]

So the root cause of the issue should be that kourier is not injecting trace information into requests as expected. Is this issue related to my kourier configuration?

apiVersion: v1
data:
  _example: |
    ################################
    #                              #
    #    EXAMPLE CONFIGURATION     #
    #                              #
    ################################

    # This block is not actually functional configuration,
    # but serves to illustrate the available configuration
    # options and document them in a way that is accessible
    # to users that `kubectl edit` this config map.
    #
    # These sample configuration options may be copied out of
    # this example block and unindented to be in the data block
    # to actually change the configuration.

    # Specifies whether requests reaching the Kourier gateway
    # in the context of services should be logged. Readiness
    # probes etc. must be configured via the bootstrap config.
    enable-service-access-logging: "true"

    # Specifies whether to use proxy-protocol in order to safely
    # transport connection information such as a client's address
    # across multiple layers of TCP proxies.
    # NOTE THAT THIS IS AN EXPERIMENTAL / ALPHA FEATURE
    enable-proxy-protocol: "false"

    # The server certificates to serve the internal TLS traffic for Kourier Gateway.
    # It is specified by the secret name in controller namespace, which has
    # the "tls.crt" and "tls.key" data field.
    # Use an empty value to disable the feature (default).
    #
    # NOTE: This flag is in an alpha state and is mostly here to enable internal testing
    #       for now. Use with caution.
    cluster-cert-secret: ""

    # Specifies the amount of time that Kourier waits for the incoming requests.
    # The default, 0s, imposes no timeout at all.
    stream-idle-timeout: "0s"

    # Specifies whether to use CryptoMB private key provider in order to
    # acclerate the TLS handshake.
    # NOTE THAT THIS IS AN EXPERIMENTAL / ALPHA FEATURE.
    enable-cryptomb: "false"

    # Configures the number of additional ingress proxy hops from the
    # right side of the x-forwarded-for HTTP header to trust.
    trusted-hops-count: "0"

    # Configures the connection manager to use the real remote address
    # of the client connection when determining internal versus external origin and manipulating various headers.
    use-remote-address: "false"

    # Specifies the cipher suites for TLS external listener.
    # Use ',' separated values like "ECDHE-ECDSA-AES128-GCM-SHA256,ECDHE-ECDSA-CHACHA20-POLY1305"
    # The default uses the default cipher suites of the envoy version.
    cipher-suites: ""
kind: ConfigMap
metadata:
  annotations:
    kubectl.kubernetes.io/last-applied-configuration: |
      {"apiVersion":"v1","data":{"_example":"################################\n#                              #\n#    EXAMPLE CONFIGURATION     #\n#                              #\n################################\n\n# This block is not actually functional configuration,\n# but serves to illustrate the available configuration\n# options and document them in a way that is accessible\n# to users that `kubectl edit` this config map.\n#\n# These sample configuration options may be copied out of\n# this example block and unindented to be in the data block\n# to actually change the configuration.\n\n# Specifies whether requests reaching the Kourier gateway\n# in the context of services should be logged. Readiness\n# probes etc. must be configured via the bootstrap config.\nenable-service-access-logging: \"true\"\n\n# Specifies whether to use proxy-protocol in order to safely\n# transport connection information such as a client's address\n# across multiple layers of TCP proxies.\n# NOTE THAT THIS IS AN EXPERIMENTAL / ALPHA FEATURE\nenable-proxy-protocol: \"false\"\n\n# The server certificates to serve the internal TLS traffic for Kourier Gateway.\n# It is specified by the secret name in controller namespace, which has\n# the \"tls.crt\" and \"tls.key\" data field.\n# Use an empty value to disable the feature (default).\n#\n# NOTE: This flag is in an alpha state and is mostly here to enable internal testing\n#       for now. Use with caution.\ncluster-cert-secret: \"\"\n\n# Specifies the amount of time that Kourier waits for the incoming requests.\n# The default, 0s, imposes no timeout at all.\nstream-idle-timeout: \"0s\"\n\n# Specifies whether to use CryptoMB private key provider in order to\n# acclerate the TLS handshake.\n# NOTE THAT THIS IS AN EXPERIMENTAL / ALPHA FEATURE.\nenable-cryptomb: \"false\"\n\n# Configures the number of additional ingress proxy hops from the\n# right side of the x-forwarded-for HTTP header to trust.\ntrusted-hops-count: \"0\"\n\n# Configures the connection manager to use the real remote address\n# of the client connection when determining internal versus external origin and manipulating various headers.\nuse-remote-address: \"false\"\n\n# Specifies the cipher suites for TLS external listener.\n# Use ',' separated values like \"ECDHE-ECDSA-AES128-GCM-SHA256,ECDHE-ECDSA-CHACHA20-POLY1305\"\n# The default uses the default cipher suites of the envoy version.\ncipher-suites: \"\"\n"},"kind":"ConfigMap","metadata":{"annotations":{},"labels":{"app.kubernetes.io/component":"net-kourier","app.kubernetes.io/name":"knative-serving","app.kubernetes.io/version":"1.16.0","argocd.argoproj.io/instance":"liks-app-knative-serving.cnhbnp01-dev-bidu-np-01","networking.knative.dev/ingress-provider":"kourier"},"name":"config-kourier","namespace":"knative-serving"}}
  creationTimestamp: "2025-02-12T06:02:16Z"
  labels:
    app.kubernetes.io/component: net-kourier
    app.kubernetes.io/name: knative-serving
    app.kubernetes.io/version: 1.16.0
    networking.knative.dev/ingress-provider: kourier
  name: config-kourier
  namespace: knative-serving
  resourceVersion: "1076858863"
  uid: 2a5dfa8d-d12b-4b36-a78d-f5492bd76f27

[linkvt]

Hi @liuyuxuan0723 ,

it seems that your config-kourier does not enable tracing which is why kourier (or more specific envoy which handles all requests in kourier) does not set the trace headers in the requests.

Tracing is automatically enabled when you set the following field in the config-kourier ConfigMap:

# example with zipkin
tracing-collector-full-endpoint: zipkin.zipkin.svc:9411/api/v2/spans

Relevant code in the net-kourier-controller: https://github.com/knative-extensions/net-kourier/blob/3a24e45c694bf2f109d66d98fca041893bb17132/pkg/reconciler/ingress/config/kourier.go#L137-L138

The missing return is a bug though, I'll go ahead and create a PR if you don't mind.

/assign

[dprotaso]

Just a heads up we're going to expose a TraceID attribute in this PR

#16168

That should work with OTel and the older x-b3-traceid header