Correlated request logging through istio-ingressgateway

[Jamie Talbot]

Hey folks, 

TL;DR - I want istio to emit a log for inbound requests to the istio-ingressgaeway with a specific MonitoredResource type and an HTTPRequest object attached to the labels, to enable correlated logging of a request through all the services that have a hand in serving it. Is that possible?

--

I have a web application consisting of 4 microservices on GKE with the istio add-on, and fronted by an Istio Ingressgateway. I would like to be able to easily see all the logs that are generated from each of these services as part of an incoming request from a client. For example, if they hit the URL `/users/jamie`. I've had some success with the parent and child structured log format to correlate logs, as described here: https://cloud.google.com/appengine/articles/logging?source=post_page---------------------------#linking_app_logs_and_requests. However, there are two entries into the application. Requests to /graphql go to graphql-service, all other requests go to web-service. This means I have to log the HTTPRequest object in both services, and have multiple loggers for each. To complicate things further, web-service sometimes calls graphql-service directly for server side rendering. In those cases, the "start" of the request is the HTTPRequest to web-service.

It occurs to me that the istio-ingress is the actual best place to log the overall HTTPRequest. At the moment, as far as I can see, the Stackdriver Monitoring add-on logs requests in the k8s_container.cluster-name.default log, where it dumps in a lot of request information. In order to make my idea work, I'd want it to instead generate a "project" MonitoredResource log to match the other services, with an attached HTTPRequest object. I believe then that each microservice could just write to their own log, which means i could look at them on a service-level, but that they would also be grouped under the top-level istio-generated request log.

How feasible is this? I've had a look at handlers.stackdriver, and I believe from istio documentation that there's a monitoredResourceType and monitoredResourceDimension field I could add to the log entry, but I've got no idea how to attach an httprequest object, and I'm kind of fumbling blindly with changes to that YAML. I also don't know if changes would stay applied over upgrades/reloads etc.

Cheers,

Jamie.

[Mary Koes]

+Ruxanda Danetiu and +Marie Cosgrove-Davies might have some ideas on Istio integrations for Stackdriver...

--
© 2016 Google Inc. 1600 Amphitheatre Parkway, Mountain View, CA 94043
 
Email preferences: You received this email because you signed up for the Google Stackdriver Discussion Google Group (google-stackdr...@googlegroups.com) to participate in discussions with other members of the GoogleStackdriver community.
---
You received this message because you are subscribed to the Google Groups "Google Stackdriver Discussion Forum" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-stackdriver-d...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/google-stackdriver-discussion/0a739b87-4481-4f3f-84a2-3eaec71f9a1e%40googlegroups.com.

[Jamie Talbot]

Hey folks, wondered if anyone had any thoughts about this :)

Best,

Jamie.

On Tuesday, July 30, 2019 at 12:01:05 PM UTC-7, Mary Koes wrote:

+Ruxanda Danetiu and +Marie Cosgrove-Davies might have some ideas on Istio integrations for Stackdriver...

On Tue, Jul 30, 2019 at 2:56 PM Jamie Talbot <ja...@pinian.co> wrote:

Hey folks, 

TL;DR - I want istio to emit a log for inbound requests to the istio-ingressgaeway with a specific MonitoredResource type and an HTTPRequest object attached to the labels, to enable correlated logging of a request through all the services that have a hand in serving it. Is that possible?

--

I have a web application consisting of 4 microservices on GKE with the istio add-on, and fronted by an Istio Ingressgateway. I would like to be able to easily see all the logs that are generated from each of these services as part of an incoming request from a client. For example, if they hit the URL `/users/jamie`. I've had some success with the parent and child structured log format to correlate logs, as described here: https://cloud.google.com/appengine/articles/logging?source=post_page---------------------------#linking_app_logs_and_requests. However, there are two entries into the application. Requests to /graphql go to graphql-service, all other requests go to web-service. This means I have to log the HTTPRequest object in both services, and have multiple loggers for each. To complicate things further, web-service sometimes calls graphql-service directly for server side rendering. In those cases, the "start" of the request is the HTTPRequest to web-service.

It occurs to me that the istio-ingress is the actual best place to log the overall HTTPRequest. At the moment, as far as I can see, the Stackdriver Monitoring add-on logs requests in the k8s_container.cluster-name.default log, where it dumps in a lot of request information. In order to make my idea work, I'd want it to instead generate a "project" MonitoredResource log to match the other services, with an attached HTTPRequest object. I believe then that each microservice could just write to their own log, which means i could look at them on a service-level, but that they would also be grouped under the top-level istio-generated request log.

How feasible is this? I've had a look at handlers.stackdriver, and I believe from istio documentation that there's a monitoredResourceType and monitoredResourceDimension field I could add to the log entry, but I've got no idea how to attach an httprequest object, and I'm kind of fumbling blindly with changes to that YAML. I also don't know if changes would stay applied over upgrades/reloads etc.

Cheers,

Jamie.

--
© 2016 Google Inc. 1600 Amphitheatre Parkway, Mountain View, CA 94043
 

Email preferences: You received this email because you signed up for the Google Stackdriver Discussion Google Group (google-stackdriver-discu...@googlegroups.com) to participate in discussions with other members of the GoogleStackdriver community.

---
You received this message because you are subscribed to the Google Groups "Google Stackdriver Discussion Forum" group.

To unsubscribe from this group and stop receiving emails from it, send an email to google-stackdriver-discussion+unsub...@googlegroups.com.

[Rory Petty]

+Javier Kohen 

On Mon, Aug 5, 2019 at 6:50 PM Jamie Talbot <ja...@pinian.co> wrote:

Hey folks, wondered if anyone had any thoughts about this :)

Best,

Jamie.

On Tuesday, July 30, 2019 at 12:01:05 PM UTC-7, Mary Koes wrote:

+Ruxanda Danetiu and +Marie Cosgrove-Davies might have some ideas on Istio integrations for Stackdriver...

On Tue, Jul 30, 2019 at 2:56 PM Jamie Talbot <ja...@pinian.co> wrote:

Hey folks, 

TL;DR - I want istio to emit a log for inbound requests to the istio-ingressgaeway with a specific MonitoredResource type and an HTTPRequest object attached to the labels, to enable correlated logging of a request through all the services that have a hand in serving it. Is that possible?

--

I have a web application consisting of 4 microservices on GKE with the istio add-on, and fronted by an Istio Ingressgateway. I would like to be able to easily see all the logs that are generated from each of these services as part of an incoming request from a client. For example, if they hit the URL `/users/jamie`. I've had some success with the parent and child structured log format to correlate logs, as described here: https://cloud.google.com/appengine/articles/logging?source=post_page---------------------------#linking_app_logs_and_requests. However, there are two entries into the application. Requests to /graphql go to graphql-service, all other requests go to web-service. This means I have to log the HTTPRequest object in both services, and have multiple loggers for each. To complicate things further, web-service sometimes calls graphql-service directly for server side rendering. In those cases, the "start" of the request is the HTTPRequest to web-service.

It occurs to me that the istio-ingress is the actual best place to log the overall HTTPRequest. At the moment, as far as I can see, the Stackdriver Monitoring add-on logs requests in the k8s_container.cluster-name.default log, where it dumps in a lot of request information. In order to make my idea work, I'd want it to instead generate a "project" MonitoredResource log to match the other services, with an attached HTTPRequest object. I believe then that each microservice could just write to their own log, which means i could look at them on a service-level, but that they would also be grouped under the top-level istio-generated request log.

How feasible is this? I've had a look at handlers.stackdriver, and I believe from istio documentation that there's a monitoredResourceType and monitoredResourceDimension field I could add to the log entry, but I've got no idea how to attach an httprequest object, and I'm kind of fumbling blindly with changes to that YAML. I also don't know if changes would stay applied over upgrades/reloads etc.

Cheers,

Jamie.

--
© 2016 Google Inc. 1600 Amphitheatre Parkway, Mountain View, CA 94043
 

Email preferences: You received this email because you signed up for the Google Stackdriver Discussion Google Group (google-stackdr...@googlegroups.com) to participate in discussions with other members of the GoogleStackdriver community.

---
You received this message because you are subscribed to the Google Groups "Google Stackdriver Discussion Forum" group.

To unsubscribe from this group and stop receiving emails from it, send an email to google-stackdriver-d...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/google-stackdriver-discussion/0a739b87-4481-4f3f-84a2-3eaec71f9a1e%40googlegroups.com.

--

© 2016 Google Inc. 1600 Amphitheatre Parkway, Mountain View, CA 94043
 

Email preferences: You received this email because you signed up for the Google Stackdriver Discussion Google Group (google-stackdr...@googlegroups.com) to participate in discussions with other members of the GoogleStackdriver community.

---
You received this message because you are subscribed to the Google Groups "Google Stackdriver Discussion Forum" group.

To unsubscribe from this group and stop receiving emails from it, send an email to google-stackdriver-d...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/google-stackdriver-discussion/51154205-c9e9-47df-a59e-a5d20fe5435a%40googlegroups.com.

[Rory Petty]

Hi Jamie,

You can use Envoy's access logs configuration (see https://istio.io/docs/tasks/telemetry/logs/access-log/) to achieve this. The configuration looks like:

apiVersion: v1

kind: ConfigMap

metadata:

labels:

addonmanager.placeholder/mode: Reconcile

app: istio

chart: istio

heritage: Tiller

release: istio

name: istio

namespace: gke-system

data:

mesh: |-

# Set enableTracing to false to disable request tracing.

enableTracing: true

# Set accessLogFile to empty string to disable access log.

accessLogFile: "/dev/stdout"

# If accessLogEncoding is TEXT, value will be used directly as the log format

# example: "[%START_TIME%] %REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\n"

# If AccessLogEncoding is JSON, value will be parsed as map[string]string

# example: '{"start_time": "%START_TIME%", "req_method": "%REQ(:METHOD)%"}'

# Leave empty to use default log format

accessLogFormat: "{ \"httpRequest\": { \"requestMethod\": \"%REQ(:METHOD)%\", \"requestUrl\": \"http://%REQ(:AUTHORITY)%%REQ(X-ENVOY-ORIGINAL-PATH?:PATH)%\", \"requestSize\": %BYTES_RECEIVED%, \"status\": %RESPONSE_CODE%, \"responseSize\": %BYTES_SENT%, \"userAgent\": \"%REQ(USER-AGENT)%\", \"remoteIp\": \"%REQ(X-FORWARDED-FOR)%\", \"serverIp\": \"%UPSTREAM_HOST%\", \"protocol\": \"%PROTOCOL%\"}, \"upstream_cluster\": \"%UPSTREAM_CLUSTER%\", \"response_flag\": \"%RESPONSE_FLAGS%\", \"logging.googleapis.com/trace\": \"%REQ(X-B3-TRACEID)%\", \"latencyMs\": %DURATION%}\n"

# Set accessLogEncoding to JSON or TEXT to configure sidecar access log

accessLogEncoding: 'TEXT'

The only issue we are hitting is that SD expects latency in seconds, whereas we can only write it in ms in Envoy (so 15 ms looks like 15 seconds on SD UI).

Let us know if that works for you and if you have any follow-up questions.

Thanks,

Rory

[Jamie Talbot]

This is great, thank you. Can't wait to try it out :) I wonder if the latency issue will cause problems with log grouping, but hopefully the traceId will control for that.

Cheers,

Jamie.

[Jamie Talbot]

Hey Rory, 

To follow up, I haven't got this working yet. The main problem seems to be that some other process is wiping out the changes I've made to the istio configmap. I can confirm the changes are saved and applied, but they get reverted back after a few minutes. Perhaps as part of the GKE istio add-on? I also am not sure where in stackdriver logging this would show up - my guess with this approach would be Kubernetes Containers -> Cluster Name -> istio-system - but nothing's there. I don't know if that is because the config was reset before any logging happened.

Best,

Jamie.

[Rory Petty]

Hi Jamie,

I will confess this is not my area of expertise and I was passing along info from other teams : ) 

+Pengyuan (Peter) Bian +Douglas Reid +Mustafa Demirhan for more details.

Thanks,

Rory

[Jamie Talbot]

Ha, no worries, it's quite an interdisciplinary thing I'm trying to do, I know :)

In the meantime, I embarked down another path, creating my own logentry, handler, and rule, combining bits from istio docs (https://istio.io/docs/reference/config/policy-and-telemetry/adapters/stackdriver/), your example, and the stackdriver add-on (server-accesslog-stackdriver.logentries and handler.stackdrivers). This is what I have so far:

apiVersion: config.istio.io/v1alpha2

kind: logentry

metadata:

labels:

k8s-app: istio

name: request-log-stackdriver

namespace: istio-system

spec:

monitored_resource_type: '"project"'

monitoredResourceDimensions:

project_id: '"pinian-app"'

severity: '"Default"'

timestamp: request.time

variables:

api_claims: request.auth.raw_claims | ""

api_key: request.api_key | request.headers["x-api-key"] | ""

api_name: api.service | ""

api_version: api.version | ""

client_trace_id: request.headers["x-client-trace-id"] | ""

destination_app: destination.labels["app"] | ""

destination_ip: destination.ip | ip("0.0.0.0")

destination_name: destination.name | ""

destination_namespace: destination.namespace | ""

destination_owner: destination.owner | ""

destination_principal: destination.principal | ""

destination_service_host: destination.service.host | ""

destination_service_name: destination.service.name | ""

destination_service_namespace: destination.service.namespace | ""

destination_uid: destination.uid | ""

destination_workload: destination.workload.name | ""

latency: response.duration | "0ms"

method: request.method | ""

protocol: request.scheme | context.protocol | "http"

received_bytes: request.total_size | 0

referer: request.referer | ""

request_id: request.headers["x-request-id"] | ""

request_operation: conditional((context.protocol | "unknown") == "grpc", request.path | "unknown", request.method | "unknown")

request_size: request.size | 0

response_code: response.code | 0

response_size: response.size | 0

response_timestamp: response.time

sent_bytes: response.total_size | 0

service_authentication_policy:

conditional((context.reporter.kind | "inbound")

== "outbound", "unknown", conditional(connection.mtls | false, "mutual_tls",

"none"))

source_app: source.labels["app"] | ""

source_ip: source.ip | ip("0.0.0.0")

source_name: source.name | ""

source_namespace: source.namespace | ""

source_owner: source.owner | ""

source_principal: source.principal | ""

source_uid: source.uid | ""

source_workload: source.workload.name | ""

trace_id: request.headers["x-b3-traceid"]

url: request.path | ""

user_agent: request.useragent | ""

service: "pinian-gateway"

---

apiVersion: config.istio.io/v1alpha2

kind: handler

metadata:

name: stackdriver

namespace: istio-system

spec:

compiledAdapter: stackdriver

params:

projectId: "pinian-app"

pushInterval: "1s"

appCredentials: true

logInfo:

request-log-stackdriver.logentry.istio-system:

payloadTemplate: '"HELLO WORLD"'

httpMapping:

status: response_code

requestSize: request_size

responseSize: response_size

latency: latency

url: url

method: method

userAgent: user_agent

referer: referer

labelNames:

- source_uid

- source_ip

- source_app

- source_principal

- source_name

- source_workload

- source_namespace

- source_owner

- destination_uid

- destination_app

- destination_ip

- destination_service_host

- destination_service_name

- destination_service_namespace

- destination_workload

- destination_name

- destination_namespace

- destination_owner

- destination_principal

- api_name

- api_version

- api_claims

- api_key

- request_operation

- protocol

- method

- url

- response_code

- response_size

- request_size

- request_id

- client_trace_id

- latency

- service_authentication_policy

- user_agent

- response_timestamp

- received_bytes

- sent_bytes

- referer

- trace_id

trace:

sampleProbability: 100

---

apiVersion: config.istio.io/v1alpha2

kind: rule

metadata:

labels:

k8s-app: istio

name: stackdriver-request-log

namespace: istio-system

spec:

actions:

- handler: stackdriver.handler

instances:

- request-log-stackdriver.logentry

match: "true"

 

This is also not working 😂 I can't tell if it's an auth thing, bad config, or if this just isn't a viable option. (The config applies, and I also don't know whether to look for any logs from istio to see whether this is broken 😂) I'd update the rule match later to isolate just the istio-ingressgateway.

Cheers,

Jamie.

To view this discussion on the web visit https://groups.google.com/d/msgid/google-stackdriver-discussion/CAJnOKH0d-L4HM4eR%3D2AJ4%3D_rSdGqy%2Bc%2B1C2Q%2B5ktW8y8_xHWUg%40mail.gmail.com.