DEV Community

Cover image for Understanding Istio Access Logs
Shardul Srivastava for AWS Community Builders

Posted on • Updated on • Originally published at shardul.dev

Understanding Istio Access Logs

Istio access logs are very helpful to understand the incoming traffic pattern. These logs are produced by the Envoy proxy and can be viewed overall at the Istio Ingress gateway or at the individual pod that is injected with the envoy proxy sidecar.

Enable Istio Access Logs

Istio access logs are not enabled by default, it can be enabled by setting the meshConfig.accessLogFile of the IstioOperator resource.

A basic istio installation with access logs enabled would look like this:



apiVersion: install.istio.io/v1alpha1
kind: IstioOperator
spec:
  meshConfig:
    accessLogFile: /dev/stdout


Enter fullscreen mode Exit fullscreen mode

Here the value /dev/stdout outputs the access logs to standard output. By default these access logs are in TEXT format i.e it looks like this :



[2022-10-23T20:38:15.413Z] "GET / HTTP/1.1" 200 - via_upstream - "-" 0 37 0 0 "-" "curl/7.35.0" "3ce3e159-9dba-4617-9e85-feb1106a682c" "nginx" "192.168.42.152:80" inbound|80|| 127.0.0.6:52375 192.168.42.152:80 192.168.59.90:34854 outbound_.80_._.nginx.default.svc.cluster.local default


Enter fullscreen mode Exit fullscreen mode

it can be changed to json by setting .spec.meshConfig.accessLogEncoding to JSON and logs would change to:



{
    "response_code_details": "via_upstream",
    "downstream_remote_address": "192.168.59.90:58478",
    "downstream_local_address": "192.168.42.152:80",
    "request_id": "e2873f51-0a42-4da4-a8e8-f711b46dea5c",
    "authority": "nginx",
    "requested_server_name": "outbound_.80_._.nginx.default.svc.cluster.local",
    "upstream_cluster": "inbound|80||",
    "path": "/",
    "bytes_sent": 37,
    "user_agent": "curl/7.35.0",
    "method": "GET",
    "upstream_local_address": "127.0.0.6:41549",
    "x_forwarded_for": null,
    "start_time": "2022-10-23T22:15:39.663Z",
    "response_code": 200,
    "upstream_transport_failure_reason": null,
    "duration": 0,
    "upstream_service_time": "0",
    "response_flags": "-",
    "upstream_host": "192.168.42.152:80",
    "route_name": "default",
    "bytes_received": 0,
    "protocol": "HTTP/1.1",
    "connection_termination_details": null
}


Enter fullscreen mode Exit fullscreen mode

Istio Access Logs Format

When Istio access logs are enabled, they are by default in this format



[%START_TIME%] \"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\" %RESPONSE_CODE% %RESPONSE_FLAGS% %RESPONSE_CODE_DETAILS% %CONNECTION_TERMINATION_DETAILS%
\"%UPSTREAM_TRANSPORT_FAILURE_REASON%\" %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% \"%REQ(X-FORWARDED-FOR)%\" \"%REQ(USER-AGENT)%\" \"%REQ(X-REQUEST-ID)%\"
\"%REQ(:AUTHORITY)%\" \"%UPSTREAM_HOST%\" %UPSTREAM_CLUSTER% %UPSTREAM_LOCAL_ADDRESS% %DOWNSTREAM_LOCAL_ADDRESS% %DOWNSTREAM_REMOTE_ADDRESS% %REQUESTED_SERVER_NAME% %ROUTE_NAME%\n


Enter fullscreen mode Exit fullscreen mode

here % is used to define a field to be printed in the access logs. To print the response code we can use %RESPONSE_CODE%. Let's look at some of the important fields here:

  1. %START_TIME% - Request start time.
  2. %RESPONSE_CODE% - Response code of the request.
  3. %RESPONSE_FLAGS% - Additional details about response. More details here
  4. %RESPONSE_CODE_DETAILS% - Response code details. More details here.
  5. %DURATION% - Total duration of the request.
  6. %UPSTREAM_HOST% - Upstream where the request is routed to such as pod. It would print the pod's IP and port where the request went. Eg - 192.168.42.152:80
  7. %REQ()% - This is used to print request headers. Eg - %REQ(-FORWARDED-FOR)% would print the X-FORWARDED-FOR request header.
  8. %RESP()% - This is used to print response headers. Eg - %RESP(CONTENT-TYPE)% would print the CONTENT-TYPE header in the response.

An exhausting list of available fields can be found here.

Customize Access Logs Format

If you want to parse your logs with a tool like Loki, json format logs would be well suited. Access logs format can be changed by setting the meshConfig.accessLogFormat.

Eg: To print json logs in a custom format



spec:
  meshConfig:
    accessLogFile: /dev/stdout
    accessLogEncoding: JSON
    accessLogFormat: |
      {
        "protocol": "%PROTOCOL%",
        "upstream_service_time": "%REQ(X-ENVOY-UPSTREAM_SERVICE_TIME)%",
        "upstream_local_address": "%UPSTREAM_LOCAL_ADDRESS%",
        "duration": "%DURATION%",
        "upstream_transport_failure_reason": "%UPSTREAM_TRANSPORT_FAILURE_REASON%",
        "route_name": "%ROUTE_NAME%",
        "downstream_local_address": "%DOWNSTREAM_LOCAL_ADDRESS%",
        "user_agent": "%REQ(USER-AGENT)%",
        "response_code": "%RESPONSE_CODE%",
        "response_flags": "%RESPONSE_FLAGS%",
        "start_time": "%START_TIME%",
        "method": "%REQ(:METHOD)%",
        "request_id": "%REQ(X-REQUEST-ID)%",
        "upstream_host": "%UPSTREAM_HOST%",
        "x_forwarded_for": "%REQ(X-FORWARDED-FOR)%",
        "client_ip": "%REQ(TRUE-Client-IP)%",
        "requested_server_name": "%REQUESTED_SERVER_NAME%",
        "bytes_received": "%BYTES_RECEIVED%",
        "bytes_sent": "%BYTES_SENT%",
        "upstream_cluster": "%UPSTREAM_CLUSTER%",
        "downstream_remote_address": "%DOWNSTREAM_REMOTE_ADDRESS%",
        "authority": "%REQ(:AUTHORITY)%",
        "path": "%REQ(X-ENVOY-ORIGINAL-PATH?:PATH)%",
        "response_code_details": "%RESPONSE_CODE_DETAILS%"
      }


Enter fullscreen mode Exit fullscreen mode

Printing Known Request and Response Headers

EnvoyProxy allows printing request headers and response headers with %REQ(X?Y):Z% and %RESP(X?Y):Z% respectively. This can be used to print any request header or response header and if the header is not present an alternative header can be given optionally.

%REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% would print the X-ENVOY-ORIGINAL-PATH header, if it doesn't exist PATH header would be printed and if even the PATH header is also not present then - would be printed instead.

So we can print all the headers that we know the name of, but how about any dynamic headers whose name changes with every request.

Istio Access logs IDK

Printing All the Request Headers and Request Body

Istio uses EnvoyProxy which is extensible by design, EnvoyFilter provides a mechanism to customize the Envoy configuration.

The HTTP Lua filter allows Lua scripts to be run during both the request and response flows. This Envoy HTTP Lua filter prints all the request headers :



apiVersion: networking.istio.io/v1alpha3
kind: EnvoyFilter
metadata:
  name: request-filter
  namespace: istio-system
spec:
  configPatches:
    - applyTo: HTTP_FILTER
      match:
        context: GATEWAY
        listener:
          filterChain:
            filter:
              name: envoy.filters.network.http_connection_manager
              subFilter:
                name: envoy.filters.http.router
      patch:
        operation: INSERT_BEFORE
        value:
          name: envoy.lua
          typed_config:
            '@type': type.googleapis.com/envoy.extensions.filters.http.lua.v3.Lua
            inlineCode: |
              -- Called on the request path.
              function envoy_on_request(request_handle)
                  request_handle:logCritical("Printing Request Headers => ")
                  for key, value in pairs(request_handle:headers()) do
                    request_handle:logCritical(key .. " => " .. value)
                  end
                  for chunk in request_handle:bodyChunks() do
                    request_handle:logCritical("Printing Request body => " .. chunk:getBytes(0, chunk:length()))
                  end
              end
  workloadSelector:
    labels:
      app: istio-ingressgateway


Enter fullscreen mode Exit fullscreen mode


kubectl apply -f istio-filter.yaml


Enter fullscreen mode Exit fullscreen mode

once applied, all the headers will be printed in the logs:



2022-10-23T23:48:39.750646Z critical  envoy lua script log: Printing Request Headers => 
2022-10-23T23:48:39.750688Z critical  envoy lua script log: :authority => 54.77.207.3
2022-10-23T23:48:39.750691Z critical  envoy lua script log: :path => /
2022-10-23T23:48:39.750693Z critical  envoy lua script log: :method => GET
2022-10-23T23:48:39.750695Z critical  envoy lua script log: :scheme => http
2022-10-23T23:48:39.750697Z critical  envoy lua script log: user-agent => Mozilla/5.0 (Windows NT 6.2;en-US) AppleWebKit/537.32.36 (KHTML, live Gecko) Chrome/56.0.3006.85 Safari/537.32
2022-10-23T23:48:39.750699Z critical  envoy lua script log: accept-encoding => gzip, deflate
2022-10-23T23:48:39.750701Z critical  envoy lua script log: accept => */*
2022-10-23T23:48:39.750714Z critical  envoy lua script log: x-forwarded-for => 192.168.59.163
2022-10-23T23:48:39.750716Z critical  envoy lua script log: x-forwarded-proto => http
2022-10-23T23:48:39.750717Z critical  envoy lua script log: x-envoy-internal => true
2022-10-23T23:48:39.750719Z critical  envoy lua script log: x-request-id => 0d1def76-2d84-4ddb-9aa3-62b2445cc1f8
2022-10-23T23:48:39.750747Z critical  envoy lua script log: x-envoy-peer-metadata-id => router~192.168.45.105~istio-ingressgateway-94b448d6d-pbsqj.istio-system~istio-system.svc.cluster.local



Enter fullscreen mode Exit fullscreen mode

Read more about EnvoyFilter here

Note: Here I am using request_handle:logCritical method because default logLevel is WARN for Istio components. request_handle:logInfo can be used, if logLevel is set to Info.

Top comments (0)